questdb icon indicating copy to clipboard operation
questdb copied to clipboard

deceptive `jit=` flag in `QueryProgress` log output

Open nwoolmer opened this issue 8 months ago • 4 comments

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

nwoolmer avatar Apr 22 '25 15:04 nwoolmer

I think I can help with this

quangdutran avatar Apr 28 '25 11:04 quangdutran

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.

InJoDave avatar Apr 29 '25 07:04 InJoDave

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.

nwoolmer avatar Apr 29 '25 07:04 nwoolmer

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]

InJoDave avatar Apr 29 '25 08:04 InJoDave