https://questdb.io logo
Powered by
Title
a

Andy Beyer

03/09/2023, 12:13 AM
Hello For QDB 7.0.1, are there some knobs to turn to control the latency? I'm using the Java ILP interface to send lines, and I'm seeing a lot of variability on the data timeliness coming back from queries. We're writing from Kafka to 6 different tables. Sometimes data returned from queries are only a few seconds behind, but often a 
SELECT COUNT(*) FROM <table>
will be frozen for 30 seconds at a particular number, so I suppose the WAL commits are bursty. I've tried calling 
flush()
on the sender API but that often leads to an exception and closure on the ILP client, so for our high throughput topic I've removed those calls and am letting the ILP client just send the lines as it sees fit. For reference, QDB is receiving about 30 MB/sec of raw Influx Iine Protocol lines (measured by 2 bytes/char*charCount), and about 3500 lines/sec overall across all topics/tables Is there a way to have the backend flush periodically so we can control the latency we see in things like Grafana graphs?
FWIW, this is running on a 
c6i.24xl
with the rest of our stack colocated (lots of docker processes) and a gp3 drive with 16k IOPS, 1000 MB/sec throughput steady state disk I/O reported by 
atop
shows ~300 MB/sec write , some (but not much) of which is Kafka, etc. and bursts up to 850 MB/sec sometimes, I assume when QDB is flushing to disk
n

Nicolas Hourcard

03/09/2023, 9:21 AM
hey @Andy Beyer welcome to our community and let us look into this
a

Alex Pelagenko

03/09/2023, 9:35 AM
Hey Andy. You are probably sending the data so called “out of order”. In this case QuestDB has to do much bigger job in comparison with “in order” data.
to check it, send here results of 
select * from sys.telemetry_wal
limit -20
a

Andy Beyer

03/09/2023, 1:54 PM
Alex, thank you. I'll give that a try and let you know what I find. I can probably see about trying to buffer data on the way in to order it by time where I can. I don't think it will always be possible given the nature of the data that is put onto the Kafka topics, but I can probably do a better job within the Quest sink application
n

Nicolas Hourcard

03/09/2023, 1:55 PM
sounds great, after this we can help you fine tune a few things to extract better performance
a

Andy Beyer

03/09/2023, 1:56 PM
awesome, thanks
I had one question about that for right now: For the scale of data I'm sending from the high throughput topics, does it make sense to configure the 
bufferCapacity
on the 
Sender
, or is it better to just let Quest pick that value internally?
a

Alex Pelagenko

03/09/2023, 2:21 PM
Re out of order ingestion, you can decrease partition sizing to hourly partition, this usually helps
a

Andy Beyer

03/09/2023, 2:22 PM
ah OK good, I had done that
a

Alex Pelagenko

03/09/2023, 2:22 PM
Re 
Sender
, can you please be more specific, are you talking ILP sender by QuestDB and what programming language?
a

Andy Beyer

03/09/2023, 2:23 PM
this is the Java ILP client, it has an option in the Builder for that parameter
a

Alex Pelagenko

03/09/2023, 2:26 PM
I'd say you need only to increase the buffer when your message doesn't fit it, default should be good
a

Andy Beyer

03/09/2023, 3:12 PM
thanks
I moved QDB to its own host and that seems to have greatly helped with data latency Here are the WAL stats from 
select * from  sys.telemetry_wal limit -25
anything stand out here? For the 
latency
column, what are the units?
a

Andrey Pechkurov

03/09/2023, 4:52 PM
latency
is in milliseconds
a

Andy Beyer

03/09/2023, 4:54 PM
i do see periods from 
wal_tables()
where the transaction number seems to stay frozen on some of the tables for up to ~1 minute at a time. I guess that's the latency I was hoping to control a little more tightly and get it down to ~3-5 seconds at most For example for some of my tables, I see something like 
select timestamp FROM '<table>' ORDER BY timestamp DESC LIMIT 5
show the most recent data available for query can be up to 1 minute stale
so possibly sending the data in-order as much as possible will help?
a

Alex Pelagenko

03/09/2023, 4:58 PM
latency is fraction of second measured from ILP commit to queryable from the table
ILP seems to batch rows in 100-700 per commit
can you find this message on start up in logs? 
WorkerPoolManager new DEDICATED pool [name=wal-apply
a

Andy Beyer

03/09/2023, 5:03 PM
questdb logs
questdb logs
a

Alex Pelagenko

03/09/2023, 5:04 PM
looks ok
if you have stale table, check it’s table id in 
select * from tables()
and then see what is in the 
sys.telemetry_wal
for that table
transactions with stale period
a

Andy Beyer

03/09/2023, 5:05 PM
here are my server settings in case I'm doing anything wrong: 
---
version: '3'

services:
  ###############
  ##  QuestDB  ##
  ###############

  questdb:
    image: questdb/questdb:7.0.1
    container_name: questdb
    restart: unless-stopped
    environment:
      QDB_SHARED_WORKER_COUNT: ${QUESTDB_SHARED_WORKER_COUNT:-44}
      QDB_LINE_TCP_WRITER_WORKER_COUNT: ${QUESTDB_SHARED_WORKER_COUNT:-44}
      QDP_LINE_TCP_CONNECTION_POOL_CAPACITY: 128
      QDB_LINE_TCP_MSG_BUFFER_SIZE: 1048576
      QDB_LINE_TCP_DEFAULT_PARTITION_BY: 'HOUR'
      QDB_LINE_DEFAULT_PARTITION_BY: 'HOUR'
    volumes:
      - questdb-data:/var/lib/questdb
    ports:
      - "9000:9000"
      - "9009:9009"
      - "8812:8812"
volumes:
  questdb-data:
a

Alex Pelagenko

03/09/2023, 5:05 PM
looks fine
a

Andy Beyer

03/09/2023, 5:19 PM
on this run, so far buffering the data in batches for ~1 second for sorting before sending over the wire to Quest seems to have helped the latency issue. the 
writeTxn
and 
sequencerTxn
are always increasing for tables that are receiving inserts as opposed to freezing for any noticeable period of time. I'm going to run some higher scale tests as well , but they take some time to start up, so I'll check back in if I run into problems with latency again.
a

Alex Pelagenko

03/09/2023, 5:19 PM
cool
I’m working on some improvements in WAL application atm, so there will be some improvements released in next release
more towards progressing many tables simultaneously. Do you write to many tables?
a

Andy Beyer

03/09/2023, 5:24 PM
we have 6 tables at the moment one of them is high throughput/data-scale and has 4 different Kafka sinks writing to it (3 partitions of the topic with a particular filter that uses decimation of the data to an extent, and 1 partition on the negation of that filter for the topic using undecimated data) the rest are written to by a single process and have varying level levels of scale/throughput but some are in the thousands rows/sec range
a

Alex Pelagenko

03/09/2023, 5:27 PM
ok, 6 tables should be fine in 7.0.1
a

Andy Beyer

03/09/2023, 6:03 PM
OK I've unfortunately hit a case where I'm running our site at lower/minimal scale where QDB has a very long latency for seeing inserted data on one of the tables (multiple minutes late)
I've got some screenshots of the various queries I'll post now
select * from tables()
-- the problem table has 
id=8
(
command-request-status
)
wal_tables()
note how the 
writerTxn
and 
sequencerTxn
are very low, and don't seem to have budged over time
select * from sys.telemetry_wal WHERE tableId=8 LIMIT -25
note the delta between the time the query was run and the values in the 
created
column
and here is just a view of the data from that table being stale same sort of delta between the time the query was run as shown in the "logs" versus the latest 
timestamp
data
docker logs questdb |& grep " E \|Except"
show no errors or exceptions
QuestDB Targeted Logs
QuestDB Targeted Logs
and finally some targeted logs from QuestDB:
appreciate any assistance looking through this
a

Alex Pelagenko

03/09/2023, 6:12 PM
Sorry I still cannot see the latency
Everything is 17:57
a

Andy Beyer

03/09/2023, 6:12 PM
sorry I meant to include the bottom "logs" part of the Web Console that query was run at 
18:01
so 4 minutes stale
despite inserts happening at ~30 rows/second in this configuration to that table
a

Alex Pelagenko

03/09/2023, 6:13 PM
Do you have data for around 18:01 in the telemetry?
Now
a

Andy Beyer

03/09/2023, 6:14 PM
I can try to pull it now, the screenshot I had was from ~13:01 when I ran the telemetry query
a

Alex Pelagenko

03/09/2023, 6:14 PM
I mean 18:01
a

Andy Beyer

03/09/2023, 6:15 PM
sorry yeah I'm EST and the timestamps are zulu so I made the same mistake 😃
wal_tables()
still showing same txn numbers:
image.png
that is the full telemetry for that table (only 4 rows, has not changed over the past ~15 mins)
a

Alex Pelagenko

03/09/2023, 6:19 PM
Weird, need logs
a

Andy Beyer

03/09/2023, 6:19 PM
you just want the entire QDB server log?
a

Alex Pelagenko

03/09/2023, 6:19 PM
Yeah for the period
From 17:55
a

Andy Beyer

03/09/2023, 6:20 PM
OK give me a few to sanitize the column names, that's the only thing that I wouldn't be able to share
qdb.log.gz
qdb.log.gz
OK sent ^
that is just the whole server log (not too many lines since I started it around 17:54Z)
and I guess in case it's any help, from inside the container this is the contents of the relevant directory on disk 
root@5d77b8a8e09a:/var/lib/questdb/db# date -u ; ls -lhrt command-request-status~8*

Thu Mar  9 18:36:51 UTC 2023

-rw-r--r-- 1 questdb questdb   0 Mar  9 18:29 command-request-status~8.lock

command-request-status~8:
total 100K
-rw-r--r-- 1 questdb questdb   49 Mar  9 17:57 _name
-rw-r--r-- 1 questdb questdb 4.0K Mar  9 17:57 _meta.prev
-rw-r--r-- 1 questdb questdb    0 Mar  9 17:57 wal1.lock
drwxrwxr-x 2 questdb questdb   98 Mar  9 17:57 txn_seq
-rw-r--r-- 1 questdb questdb 4.0K Mar  9 17:57 _txn
-rw-r--r-- 1 questdb questdb 4.0K Mar  9 17:57 _meta
-rw-r--r-- 1 questdb questdb 4.0K Mar  9 17:57 _cv
drwxrwxr-x 2 questdb questdb  153 Mar  9 17:57 2023-03-09T17
drwxrwxr-x 3 questdb questdb   29 Mar  9 17:57 wal1
-rw-r--r-- 1 questdb questdb 4.0K Mar  9 18:09 symbolColumn1.v
-rw-r--r-- 1 questdb questdb 4.0K Mar  9 18:09 symbolColumn1.o
-rw-r--r-- 1 questdb questdb 8.0K Mar  9 18:09 symbolColumn1.k
-rw-r--r-- 1 questdb questdb 8.0K Mar  9 18:09 symbolColumn1.c
-rw-r--r-- 1 questdb questdb 4.0K Mar  9 18:09 symbolColumn2.v
-rw-r--r-- 1 questdb questdb 4.0K Mar  9 18:09 symbolColumn2.o
-rw-r--r-- 1 questdb questdb 4.0K Mar  9 18:09 symbolColumn2.k
-rw-r--r-- 1 questdb questdb 4.0K Mar  9 18:09 symbolColumn2.c
-rw-r--r-- 1 questdb questdb  33K Mar  9 18:29 _txn_scoreboard
-rw-r--r-- 1 questdb questdb 4.0K Mar  9 18:29 _todo_
another data point: when I killed the Kafka Streams Sink application that was writing to that table, which calls 
close()
on the 
LineTcpSender
during a shutdown hook and then terminates and restarts the Java process I immediately saw the 
select count(*)
for that table jump from ~241 rows to ~32000 rows so perhaps I need to periodically call 
close()
on the 
LineTcpSender
instances and recreate them? Instead of just periodically calling 
flush()
?
currently the instance is created at the start of the stream processing application and held open for the lifetime, and it is only accessed exclusively (one thread at a time)
OK so using that as a workaround (calling 
close()
periodically on the Java ILP 
LineTcpSender
) does seem to be a more forceful way of flushing and reducing latency is that recommended as the usage pattern, or just a workaround for now?
a

Alex Pelagenko

03/09/2023, 10:06 PM
I see in the log lines 
2023-03-09T18:04:02.715310Z I i.q.c.TableWriter processing WAL [path=/var/lib/questdb/db/device-status~6/wal6/1, roLo=5310, seqTxn2794, roHi=5334, tsMin=2023-03-09T18:03:57.057000Z, tsMax=2023-03-09T18:04:01.907000Z, commitToTimestamp=1969-12-31T23:59:59.999999Z]
2023-03-09T18:04:02.716667Z I i.q.c.TableWriter processing WAL [path=/var/lib/questdb/db/device-status~6/wal4/3, roLo=5813, seqTxn2795, roHi=5839, tsMin=2023-03-09T18:03:56.735000Z, tsMax=2023-03-09T18:04:01.872000Z, commitToTimestamp=1969-12-31T23:59:59.999999Z]
2023-03-09T18:04:02.717925Z I i.q.c.TableWriter processing WAL [path=/var/lib/questdb/db/device-status~6/wal5/3, roLo=5594, seqTxn2796, roHi=5618, tsMin=2023-03-09T18:03:56.875000Z, tsMax=2023-03-09T18:04:01.872000Z, commitToTimestamp=1969-12-31T23:59:59.999999Z]
2023-03-09T18:04:02.719238Z I i.q.c.TableWriter processing WAL [path=/var/lib/questdb/db/device-status~6/wal2/2, roLo=6087, seqTxn2797, roHi=6113, tsMin=2023-03-09T18:03:56.736000Z, tsMax=2023-03-09T18:04:01.873000Z, commitToTimestamp=1969-12-31T23:59:59.999999Z]
2023-03-09T18:04:02.720473Z I i.q.c.TableWriter processing WAL [path=/var/lib/questdb/db/device-status~6/wal3/2, roLo=6149, seqTxn2798, roHi=6174, tsMin=2023-03-09T18:03:56.855000Z, tsMax=2023-03-09T18:04:01.871000Z, commitToTimestamp=1969-12-31T23:59:59.999999Z]
2023-03-09T18:04:02.722016Z I i.q.c.TableWriter processing WAL [path=/var/lib/questdb/db/device-status~6/wal7/1, roLo=5101, seqTxn2799, roHi=5106, tsMin=2023-03-09T18:04:00.907000Z, tsMax=2023-03-09T18:04:01.872000Z, commitToTimestamp=1969-12-31T23:59:59.999999Z]
2023-03-09T18:04:02.723456Z I i.q.c.TableWriter processing WAL [path=/var/lib/questdb/db/device-status~6/wal1/2, roLo=6799, seqTxn2800, roHi=6822, tsMin=2023-03-09T18:03:57.057000Z, tsMax=2023-03-09T18:04:01.871000Z, commitToTimestamp=1969-12-31T23:59:59.999999Z]
2023-03-09T18:04:02.724925Z I i.q.c.TableWriter processing WAL [path=/var/lib/questdb/db/device-status~6/wal8/1, roLo=4348, seqTxn2801, roHi=4373, tsMin=2023-03-09T18:03:56.872000Z, tsMax=2023-03-09T18:04:01.873000Z, commitToTimestamp=294247-01-10T04:00:54.775807Z]
2023-03-09T18:04:02.725389Z I i.q.c.TableWriter sorting WAL [table=device-status, ordered=true, lagRowCount=153, rowLo=4348, rowHi=4373]
2023-03-09T18:04:02.725525Z I i.q.c.TableWriter o3 partition task [table=device-status, partitionIsReadOnly=false, srcOooBatchRowSize=178, srcOooLo=0, srcOooHi=177, srcOooMax=178, o3RowCount=178, o3LagRowCount=0, srcDataMax=34051, o3TimestampMin=2023-03-09T18:03:56.735000Z, o3Timestamp=2023-03-09T18:03:56.735000Z, o3TimestampMax=2023-03-09T18:04:01.907000Z, partitionTimestamp=2023-03-09T18:00:00.000000Z, partitionIndex=4, partitionSize=34229, maxTimestamp=2023-03-09T18:04:00.871000Z, last=true, append=false, pCount=1, flattenTimestamp=true, memUsed=61788072304]
2023-03-09T18:04:02.739893Z I i.q.c.TableWriter closing last partition [table=device-status]
2023-03-09T18:04:02.743384Z I i.q.c.TableWriter merged partition [table=`device-status`, ts=2023-03-09T18:00:00.000000Z, txn=1019]
2023-03-09T18:04:02.746332Z I i.q.c.TableWriter switched partition [path='/var/lib/questdb/db/device-status~6/2023-03-09T18.1019']
2023-03-09T18:04:02.756696Z I i.q.c.TableWriter removed [path=/var/lib/questdb/db/device-status~6/2023-03-09T18.1018]
2023-03-09T18:04:02.756757Z I i.q.c.w.ApplyWal2TableJob WAL apply job finished [table=device-status, transactions=8, rows=178, time=41ms, rate=4294rows/s, physicalWrittenRowsMultiplier=593032.88]
2023-03-09T18:04:02.756796Z I i.q.c.p.WriterPool << [table=`device-status~6`, thread=71]
Which mean that at 18:04:02 data with timestamps of 
tsMax=2023-03-09T18:04:01.873000Z
was written
so that at 
2023-03-09T18:04:02.724925Z
it says 
processing WAL [path=... seqTxn2801, tsMin=2023-03-09T18:03:56.872000Z, tsMax=2023-03-09T18:04:01.873000Z, commitToTimestamp=294247-01-10T04:00:54.775807Z]
it means that data committed was in range of [18:03:56.872, 18:04:01.873] and it’s written to the table at 18:04:02.724
a

Andy Beyer

03/09/2023, 10:10 PM
OK so that information combined with the fact that doing a 
close()
on the Java ILP client causes the data to show up in the server probably means that the client isn't actually sending the data to the server and that's why the data is stale on the server side?
a

Alex Pelagenko

03/09/2023, 10:14 PM
also last time you executed 
select timestamp from 'device-status' ORDER BY timestamp DESC LIMIT 5
was 17:58
not 18:01
a

Andy Beyer

03/09/2023, 10:14 PM
yeah, I was looking more at the 
command-request-status
in that case
which was the stale table
a

Alex Pelagenko

03/09/2023, 10:15 PM
ah, let me have a look at that table then
I don’t see anything hitting that table after 1 initial transaction at 17:57
no errors from ILP either
a

Andy Beyer

03/09/2023, 10:25 PM
OK then yeah I think for some reason the Java ILP client isn't sending the data, even when I call 
flush()
a

Alex Pelagenko

03/09/2023, 10:25 PM
what’s your sending code?
a

Andy Beyer

03/09/2023, 10:26 PM
Sender.java
Sender.java
this is the crux of it
with some periodic calls to 
flush()
and all code has exclusive access to the 
sender
instance when making any calls to it
a

Alex Pelagenko

03/09/2023, 10:28 PM
is it constant low rate sending? like 1 row in 0.5 secs?
a

Andy Beyer

03/09/2023, 10:28 PM
no, it is sending much more than that
a

Alex Pelagenko

03/09/2023, 10:31 PM
can it happen that 
measurmentName
sent incorrectly? would you be able to see that the data from this table landed in another?
a

Andy Beyer

03/09/2023, 10:31 PM
no, that is a static preconfigured value for the sink
a

Alex Pelagenko

03/09/2023, 10:38 PM
flush()
sends all, also data is sent on buffer overflow but everything looks like nothing hits QuestDB
a

Andy Beyer

03/09/2023, 10:39 PM
correct, and calling 
close()
periodically and recreating the sender instance (instead of 
flush()
) seems to fix the issue I was seeing
a

Alex Pelagenko

03/09/2023, 10:39 PM
I guess I can only suggest to either create a reproducer or sniff network traffic
a

Andy Beyer

03/09/2023, 10:39 PM
OK sounds good, thank you for your help at least it seems to be narrowed to the client side
and not something strange within the DB / WAL system itself
a

Alex Pelagenko

03/09/2023, 10:40 PM
yes, I lean towards client interaction in this case
3 Views
#users-publicJoin Slack
Powered by