huge latency on read operations when database is being updated

[antonvlasov]

In case table is updated with different connection, read operations with do not return results for long time. I've run similar test with fdb in python on same database and got good latency as expected (<1s for same settings). Also same test in go gives decent latency on sqlite3 database, therefore all statements are correct. Please comment on this bug and possible workaraunds.

I've tested this with local database created with isql-fb with command CREATE DATABASE '/opt/firebird/database.fdb' USER 'SYSDBA' PASSWORD 'changeit';. Database contains a single table created with command create table numbers (i int not null primary key);

Here is code for measuring latency in go.

package main

import (
	"database/sql"
	"fmt"
	"log"
	"sync"
	"time"

	_ "github.com/nakagami/firebirdsql"
)

const (
	host     = "localhost"
	database = "/opt/firebird/database.fdb"
	user     = "SYSDBA"
	password = "changeit"

	benchLenghtSeconds = 10.0
	msgCount           = 10
	readInterval       = 1
)

var (
	writeDB    *sql.DB
	readDB     *sql.DB
	clearDB    *sql.DB
	writeTimes = make(map[int]time.Time)
	readTimes  = make(map[int]time.Time)
)

func read(wg *sync.WaitGroup) {
	defer wg.Done()

	lastRead := -1

	for lastRead < msgCount-1 {
		fmt.Println("read loop start")

		rows, err := readDB.Query("SELECT i from numbers WHERE i>?", lastRead)
		if err != nil {
			log.Fatal(err)
		}

		fmt.Println("query done")

		timestamp := time.Now()

		for rows.Next() {
			fmt.Println(`in "next" loop`)
			var i int
			if err := rows.Scan(&i); err != nil {
				log.Fatal(err)
			}

			readTimes[i] = timestamp
			fmt.Println("read ", i)
			lastRead = i
		}
		fmt.Println(`after "next" loop`)

		rows.Close()

		time.Sleep(readInterval * time.Second)
	}
}

func write(wg *sync.WaitGroup) {
	defer wg.Done()

	stmt, err := writeDB.Prepare("INSERT INTO numbers (i) VALUES (?);")
	if err != nil {
		log.Fatal(err)
	}

	defer stmt.Close()

	for i := 0; i < msgCount; i++ {
		_, err := stmt.Exec(i)
		if err != nil {
			log.Fatal(err)
		}

		writeTimes[i] = time.Now()
		fmt.Println("wrote ", i)

		time.Sleep(time.Duration(benchLenghtSeconds/msgCount) * time.Second)
	}
}

func clearNumbers() {
	if _, err := clearDB.Exec("DELETE FROM numbers;"); err != nil {
		log.Fatal(err)
	}
}

func main() {
	var err error

	writeDB, err = sql.Open("firebirdsql", fmt.Sprintf("%s:%s@%s/%s", user, password, host, database))
	if err != nil {
		log.Fatal(err)
	}
	defer writeDB.Close()

	readDB, err = sql.Open("firebirdsql", fmt.Sprintf("%s:%s@%s/%s", user, password, host, database))
	if err != nil {
		log.Fatal(err)
	}
	defer writeDB.Close()

	clearDB, err = sql.Open("firebirdsql", fmt.Sprintf("%s:%s@%s/%s", user, password, host, database))
	if err != nil {
		log.Fatal(err)
	}
	defer writeDB.Close()

	clearNumbers()

	wg := sync.WaitGroup{}
	wg.Add(2)
	go read(&wg)
	go write(&wg)
	wg.Wait()

	mean := 0.0
	for i, t := range writeTimes {
		mean += readTimes[i].Sub(t).Seconds()
	}
	mean /= msgCount

	fmt.Printf("mean latency: %v s\n", mean)

	clearNumbers()
}

Output:

read loop start
wrote  0
query done
after "next" loop
wrote  1
read loop start
query done
after "next" loop
wrote  2
read loop start
query done
after "next" loop
wrote  3
read loop start
query done
after "next" loop
wrote  4
read loop start
query done
after "next" loop
wrote  5
read loop start
query done
after "next" loop
wrote  6
read loop start
query done
after "next" loop
wrote  7
read loop start
query done
after "next" loop
wrote  8
read loop start
query done
after "next" loop
wrote  9
read loop start
query done
after "next" loop
read loop start
query done
in "next" loop
read  0
in "next" loop
read  1
in "next" loop
read  2
in "next" loop
read  3
in "next" loop
read  4
in "next" loop
read  5
in "next" loop
read  6
in "next" loop
read  7
in "next" loop
read  8
in "next" loop
read  9
after "next" loop
mean latency: 5.5446701527 s

fdb test

import fdb
from timeit import default_timer
import asyncio

HOST = 'localhost'
DATABAASE = '/opt/firebird/database.fdb'
USER = 'SYSDBA'
PASSWORD='changeit'

BENCH_LENGTH_SECONDS = 10.0
MSG_COUNT=10
READ_INTERVAL = 1

con_write = fdb.connect(
    host=HOST, database=DATABAASE,
    user=USER, password=PASSWORD
  )

con_read = fdb.connect(
    host=HOST, database=DATABAASE,
    user=USER, password=PASSWORD
  )

con_cleanup = fdb.connect(
    host=HOST, database=DATABAASE,
    user=USER, password=PASSWORD
  )
  
write_cur = con_write.cursor()
read_cur = con_read.cursor()
cleanup_cur = con_cleanup.cursor()

write_times = {}
read_times = {}

async def write():
  for i in range(MSG_COUNT):
    write_cur.execute("INSERT INTO numbers (i) VALUES (?);",(i,))
    con_write.commit()
    
    write_times[i]=default_timer()
    
    await asyncio.sleep(BENCH_LENGTH_SECONDS/MSG_COUNT)
  
async def read():
  last_read = -1
  while last_read<MSG_COUNT-1:
    res = read_cur.execute("SELECT i from numbers WHERE i>?;",(last_read,)).fetchall()
    timestamp = default_timer()
    
    for row in res:
      read_times[row[0]]=timestamp
      last_read = row[0]

    await asyncio.sleep(READ_INTERVAL)


async def main():
    f1 = loop.create_task(write())
    f2 = loop.create_task(read())
    await asyncio.wait([f1, f2])

# cleanup
cleanup_cur.execute('DELETE FROM numbers;')
con_cleanup.commit()

loop = asyncio.get_event_loop()
loop.run_until_complete(main())
loop.close()

# cleanup
cleanup_cur.execute('DELETE FROM numbers;')
con_cleanup.commit()

# count latency

diff = 0.0
for i,t in write_times.items():
  diff+=read_times[i]-t

diff/=MSG_COUNT

print(f'mean latency: {diff*1000} ms')

output:

mean latency: 1.1342148995026946 ms