tasklite polls stdin for 0.5 seconds before printing tasks list

[vbmithr]

15:48:28.083214 poll([{fd=0, events=POLLIN}], 1, 0) = 0 (Timeout)
15:48:28.083246 pselect6(1, [0], [], NULL, {tv_sec=0, tv_nsec=0}, NULL) = 0 (Timeout)
15:48:28.083283 pselect6(1, [0], [], NULL, {tv_sec=0, tv_nsec=499999000}, NULL) = 0 (Timeout)
15:48:28.584388 futex(0x2d95228, FUTEX_WAKE_PRIVATE, 1) = 1

Haven't checked the code for why there is this waiting time, but it's kinda annoying.

[ad-si]

Mh, maybe because of the hooks: https://tasklite.org/cli/hooks/main

But I don't think I have any polling going on my system (macOS). Might be a Linux problem?
How can I reproduce this output?

[vbmithr]

trace.log

Just run tasklite without arguments.
You can see in logs

10:46:34.103099 poll([{fd=0, events=POLLIN}], 1, 0) = 0 (Timeout)
10:46:34.103185 pselect6(1, [0], [], NULL, {tv_sec=0, tv_nsec=0}, NULL) = 0 (Timeout)
10:46:34.103289 pselect6(1, [0], [], NULL, {tv_sec=0, tv_nsec=499999000}, NULL) = 0 (Timeout)
10:46:34.604083 futex(0x2e21d68, FUTEX_WAKE_PRIVATE, 1) = 1
10:46:34.604233 futex(0x2e21d00, FUTEX_WAKE_PRIVATE, 1) = 1
10:46:34.604368 ioctl(0, TCGETS, {c_iflag=ICRNL|IXON, c_oflag=NL0|CR0|TAB0|BS0|VT0|FF0|OPOST|ONLCR, c_cflag=B38400|CS8|
CREAD, c_lflag=ISIG|ECHOE|ECHOK|IEXTEN|ECHOCTL|ECHOKE, ...}) = 0

It happens only on listing commands.

[ad-si]

What did you use to generate the trace.log file? strace?

I just checked the profiling output of GHC (https://downloads.haskell.org/ghc/9.6-latest/docs/users_guide/profiling.html), but couldn't see anything suspicious.

If you have an idea how this could be debugged, any help would be highly appreciated!

[vbmithr]

strace yes. I tried to understand too but the code is a bit cryptic for me.

[vbmithr]

Given the trace, the lag happens between a stat to main.db-wal and main.db. As if the library tried to poll stdin in between…?

[vbmithr]

tl.log

[ad-si]

If SQLite makes a request in WAL mode it first checks main.db-wal (basically a cache) and then main.db for the data. So it might be a bug in the SQLite library?
=> https://github.com/IreneKnapp/direct-sqlite
But I can't imagine why it would poll stdin in between.

[apraga]

trace_wsl2.txt

On WSL2, there are some timeouts, that may be related ? If that can help

rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
poll([{fd=0, events=POLLIN}], 1, 0)     = 0 (Timeout)
poll([{fd=2, events=POLLOUT}], 1, 0)    = 1 ([{fd=2, revents=POLLOUT}])
write(2, "\33", 1 1
poll([{fd=2, events=POLLOUT}], 1, 0)    = 1 ([{fd=2, revents=POLLOUT}])
write(2, "]", 1])                        = 1
poll([{fd=2, events=POLLOUT}], 1, 0)    = 1 ([{fd=2, revents=POLLOUT}])
write(2, "1", 11)                        = 1
poll([{fd=2, events=POLLOUT}], 1, 0)    = 1 ([{fd=2, revents=POLLOUT}])
write(2, "1", 11)                        = 1
poll([{fd=2, events=POLLOUT}], 1, 0)    = 1 ([{fd=2, revents=POLLOUT}])
write(2, ";", 1;)                        = 1
poll([{fd=2, events=POLLOUT}], 1, 0)    = 1 ([{fd=2, revents=POLLOUT}])
write(2, "?", 1?)                        = 1
poll([{fd=2, events=POLLOUT}], 1, 0)    = 1 ([{fd=2, revents=POLLOUT}])
write(2, "\33", 1 1
poll([{fd=2, events=POLLOUT}], 1, 0)    = 1 ([{fd=2, revents=POLLOUT}])
write(2, "\\", 1\)                       = 1
poll([{fd=0, events=POLLIN}], 1, 0)     = 0 (Timeout)
pselect6(1, [0], [], NULL, {tv_sec=0, tv_nsec=0}, NULL) = 0 (Timeout)
pselect6(1, [0], [], NULL, {tv_sec=0, tv_nsec=499982000}, NULL) = 0 (Timeout)
futex(0x2d95228, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x2d951c0, FUTEX_WAKE_PRIVATE, 1) = 1

[apraga]

Edit : on my laptop with Gentoo, I have the same message about the timeout above but there is no noticeable delay when running commands.