TaskRunner tracking bug

[swankjesse]

This issue is intended to help me organize what’s done and needs doing for TaskRunner.

• API
• Initial implementation
• ConnectionPool
• DiskLruCache
• HTTP/2 writer and push
• WebSockets
• MockWebServer
• HTTP/2 listeners
• Daemon threads
• Fewer context switches (details)
• Consistent queue and task names
• Strict mode and/or other diagnostics for stuck queues (details)
• Tools for understanding real-world use (details)
• Re-evaluate how tryCancel() opt-in vs. opt-out
• Better task names

See also

• Simplify test code
• Detect HTTP/2 liveness
• Document debug logging

[swankjesse]

To improve visibility I think I'll borrow from what we do for HTTP/2 frames: use logger.fine() to print events and metrics. If you know it exists you can turn it on, but no public API.

[swankjesse]

I wanna build debug logging for tasks. Here’s a sketch of a sample log:

Q1 ▌ scheduled after 100 ms: OkHttp example.com ping
Q1 ▌▌ scheduled after 200 ms: OkHttp example.com[3] writeSynReset
Q1 ▌▌ starting: OkHttp example.com ping
Q1 ▌▌ executed in 130 ms (next after 100 ms): OkHttp example.com ping
Q1 ▌▌ starting (31 ms late): OkHttp example.com[3] writeSynReset
Q1 ▌▌ executed in 2 ms: OkHttp example.com[3] writeSynReset
Q2 ▌ posted: OkHttp ConnectionPool

Notes:

• Q1, Q2 etc. is queue name. This is a process-wide ID.
• ▌▌ is queue size in tasks. This includes task being just-added or just-completed.
• scheduled for delayed tasks, posted for immediate tasks.
• units are ms, µs, or s. No nanos in logs; just truncate to 0 µs.
• "starting" includes start delay like (31 ms late) if task start is more than 10 ms later than scheduled. This will be due to busy CPU or a preceding task going overtime.
• need to measure execution time!

These logs will be off by default. Enable FINE logging on TaskRunner to get logs.

[Egorand]

A couple thoughts:

• Probably worth keeping logs indented to the same level after the queue size, otherwise it feels like the logs with the same indentation are grouped, while they're not. Perhaps having a uniform indentation that grows if the queue gets bigger could work?

Q1 ▌     scheduled after 100 ms: OkHttp example.com ping
Q1 ▌▌    scheduled after 200 ms: OkHttp example.com[3] writeSynReset
Q1 ▌▌▌   starting: OkHttp example.com ping
Q1 ▌▌▌▌  executed in 130 ms (next after 100 ms): OkHttp example.com ping
Q1 ▌▌    starting (31 ms late): OkHttp example.com[3] writeSynReset
Q1 ▌▌▌▌▌ executed in 2 ms: OkHttp example.com[3] writeSynReset
Q2 ▌▌▌▌▌▌▌▌▌▌ posted: OkHttp ConnectionPool
Q2 ▌▌▌▌▌▌▌    posted: OkHttp ConnectionPool
Q2 ▌▌▌▌▌▌▌▌▌  posted: OkHttp ConnectionPool
Q2 ▌     posted: OkHttp ConnectionPool

• How about printing scheduled, starting, executed and posted in bold?

[yschimke]

@swankjesse Nice work on this, impressive to see the progression!

[swankjesse]

I think I'm ready to call this complete. Anything else you wanna see for observability or troubleshooting?

[yschimke]

@swankjesse let's follow up with that based on working through flaky CI tests. That's my main goal - can we use our own tools to after the fact debug

[swankjesse]

No further action for this issue. Will work through flaky tests!