Timing profiles don't include non-CPU times

[andrewbanchich]

When debugging slow compile times, I ran cargo rustc --profile check --manifest-path ./my-crate/Cargo.toml -- -Zself-profile. summarize gave Total cpu time: 2.6826241s, but the former command said it finished in 1 minute 45 seconds.

The issue turned out to be SQLx query macros, which make network requests to a live database when expanded.

I think it would be useful to include that information in timing profiles.

[jonas-schievink]

"CPU time" generally is the time the process is scheduled on a CPU. Network requests are not included in that time, since they are an I/O operation.

[andrewbanchich]

Yes, but it would have been helpful to have timings include the network / non-CPU times as well to make it more obvious what the problem was.

Is that something which could be added?

[wesleywiser]

-Zself-profile measures wall-clock time not CPU time so it should have picked this up.

[andrewbanchich]

Thanks for clarifying @wesleywiser . So should the output file be changed to not say Total cpu time?

[lqd]

Is there a way to reproduce the issue (ideally, without sqlx and an actual DB) ?

For example, I am unable to trigger this behavior if I just thread::sleep for a few seconds in a:

• custom derive
• function-like proc macro
• attribute macro

-Z self-profile seemed to take all 3 in into account in my test: the time sleeping was accounted for in the expand_crate query.

Could multiple builds without changes have been involved ? So that maybe some of the proc macros weren't re-run on the subsequent profiled run (I also believe sqlx has a way to cache the results of their network requests and query analysis between builds, but that doesn't seem to be involved here).

[andrewbanchich]

@lqd

Is there a way to reproduce the issue (ideally, without sqlx and an actual DB) ?

I'm not sure, I haven't used any other macros that make network requests before.

Could multiple builds without changes have been involved ?

For these stats, I built the entire project, added a newline to invalidate the cache, recorded the time, removed the newline, profiled it with timings, so to the best of my understanding it should be an apples to apples comparison.

Also, the summarize command only says Total cpu time: 2.6826241s, but it was actually much longer than that. It just didn't record it in the total CPU time stat.