Search code examples
questdb

Interpreting timings for queries in QuestDB logs


I am running a very simple query on QuestDB and when I check the timings in the logs I can see they fluctuate a lot. How do I interpret the query timings?

2024-11-27T08:47:46.288120Z I i.q.c.h.p.JsonQueryProcessorState [41006026692394] timings [compiler: 209519, count: 73984, execute: 306691, q=`SELECT DISTINCT ticker FROM trades LIMIT 1;`]

2024-11-27T08:47:53.082521Z I i.q.c.h.p.JsonQueryProcessorState [52941740815685] timings [compiler: 0, count: 1965822, execute: 137960, q=`SELECT DISTINCT ticker FROM trades LIMIT 1;`]


Solution

  • First of all, the timings are all in nanoseconds. With this, there are three parts to consider:

    • compiler stands for the time taken by SQL compilation. When the query plan is cached (think, prepared statement), it'll be zero. If you are using the REST API and you send a query with the exact same time multiple times, it will also come from the cache, which would explain the timing 0 for your second query.
    • count stands for time taken to count all rows - this is done when you specify count=true query parameter if using the REST API, and you can set it to false when not needed.
    • execute stands for query execution, i.e. time taken to retrieve the data and write it to the socket. This might vary depending on server workload, but also on if the data is hot or cold. When QuestDB needs to access a data partition to read some data, it will keep those pages in memory and will reuse them on subsequent queries. Those queries tend to be much faster. Eventually the OS will reclaim the memory used for those pages when reading other partitions, but if you send a few queries in a row using the same columns and time partitions, you will notice the first one always takes longer than the others.