deceptive `jit=` flag in `QueryProgress` log output
To reproduce
When running queries, query progress is reported using a pair of exe and fin statements. Unfortunately, the jit label is not implemented correctly.
This means you can start a query with no JIT, but finish it with JIT.
2025-04-22T15:01:01.433405Z I i.q.g.e.QueryProgress exe [id=837, sql=`tab where col1 in ($1) and status = $2 and ts >= 0 latest on ts partition by status `, principal=admin, cache=true, jit=false]
2025-04-22T15:01:01.433538Z I i.q.g.e.QueryProgress fin [id=837, sql=`tab where col1 in ($1) and status = $2 and ts >= 0 latest on ts partition by status `, principal=admin, cache=true, jit=true, time=135800]
This is because logStart accepts a boolean jit argument. This is populated by checking if the query uses a compiled filter.
However, logEnd and logError do not have this. Instead, they report whether or not jit is enabled globally:
boolean isJit = executionContext.getJitMode() != SqlJitMode.JIT_MODE_DISABLED;
This leads to confusing logs.
QuestDB version:
Master (8.3.0+)
OS, in case of Docker specify Docker and the Host OS:
N/A
File System, in case of Docker specify Host File System:
N/A
Full Name:
Nick Woolmer
Affiliation:
QuestDB
Have you followed Linux, MacOs kernel configuration steps to increase Maximum open files and Maximum virtual memory areas limit?
- [x] Yes, I have
Additional context
No response
I think I can help with this
Hi @nwoolmer regarding this issue I have gone through the code. Do you want logEnd and logError to be configurable same like logStart. Or should logStart also read from the global setting for jit? I think both makes sense. I can work with @quangdutran to fix this.
JIT should behave consistently across all the log functions. In this case, it should tell you if a compiled filter was used, not just whether JIT is globally possible.
Hi @nwoolmer I have raised a PR for this fix https://github.com/questdb/questdb/pull/5637. Could you please review the same?
Testing log
2025-04-29T08:08:16.429337Z I i.q.g.e.QueryProgress fin [id=21, sql=CREATE TABLE 'Employee' (name VARCHAR);, principal=admin, cache=false, jit=false, time=-1739811550464686]
2025-04-29T08:08:16.439802Z I i.q.g.e.QueryProgress exe [id=22, sql=SELECT instance_name, instance_rgb, current_user, principal=admin, cache=true, jit=false]
2025-04-29T08:08:16.440241Z I i.q.g.e.QueryProgress fin [id=22, sql=SELECT instance_name, instance_rgb, current_user, principal=admin, cache=true, jit=false, time=445500]
2025-04-29T08:08:56.929177Z E i.q.g.e.QueryProgress err [id=-1, sql=select * from emp, principal=admin, cache=false, jit=false, time=826000, msg=table does not exist [table=emp], errno=0, pos=14]
2025-04-29T08:12:44.867342Z I i.q.c.p.ReaderPool closed 'sys.column_versions_purge_log' [at=0:0, reason=IDLE]