Why a thread can run for less than 100% wall time?
As I understand, "wall time" measures simply time passed, from start to finish. This means that any thread that started before profiling began, and didn't finish during profiling, should have its total run time equal to profiling time. But that's not the case: when I profiled our application, I saw several threads that used about half total time. I used tracing for profiling and wall time measurement.
More info here: http://stackoverflow.com/questions/4946164/how-can-a-thread-use-less-than-100-wall-time
What does that mean? How can a thread use less than 100% wall time?
Please sign in to leave a comment.
Hi,
Could you please send me snapshot at which you see this.
It will be fine if you use dropbox.com or our ftp://ftp.intellij.net/.uploads/ or any other filesharing service.
For private communication please use email Ivan.Shakhov@jetbrains.com
WRB, Ivan Shakhov
Link to snapshot: http://dl.dropbox.com/u/3440976/2000_bots_ai.dtp
The threads in question are named "InstanceRunner" 0 through 4.
The profiling took about 100 sec, most threads report 100 sec or close time. The "Network" one is actually 3 threads that dotTrace compressed into one (come to think of it, it should have shown 300 sec, not 274. But at least 274 is close).
Hi,
Threads are less than 100% because you have used "Don't start immediatelly" checkbox and when you started to profile the thread existed and already spended some time.
Regarding the "Network" thread - yes we do merge threads with the same name. And it is less than 300 sec because of the same reason ("Don't start immediatelly").
Hope this helps.
Besides that, when you see Thread #N - 3.xxx* ms. The "star" is indicating that thread started before we start to record its time.
WRB, Ivan Shakhov
Um, I still don't understand. So what if it started before profiling started? It has been running when profiling started, and it still was running when profiling finished. Also, all other threads started before profiling too! Actually, all these threads (except threadpool ones) were started right at the start of the application.
The "InstanceRunner" threads in my snapshot clearly differ from all other threads. What I want to ultimately understand is _why_ they differ? Start time certainly does not explain it.
Are you sure that profiling took about 100 sec?
We made additional investigation of the snapshot and it seems that "Network" thread is not merged.
"Network" thread is main and thus its time shold be the same as profiling time.
All other threads could have started before profiling start and finish before profiling end
WRB, Ivan Shakhov
No, "Network" is definitely NOT the main thread. "Thread #1" is the main thread. As you can see, it spent 100% of its time in wait (which is correct). And definitely, no thread finished before profiling ended: they're all continuously running threads, that can only stop if application quits or crashes.
Also, I didn't time profiling exactly, but it took close to 1.5 minutes, and certainly not more than 4. Which means, total time must be about 100 seconds.
Can you send us the application sources?
Maybe some simple example?
No, I don't think providing source code is possible. It's quite large, to say nothing of legal and privacy concerns. The code is described in general in my Stackoverflow post; I can answer more specific questions if you have any.
One thing I've been thinking: our application has pretty high thread contention rate. Might it be that the threads in question spent most of their time waiting to enter a lock? That's an awful lot of time to spend waiting, though.
Edit: I tested this assumption and apparently it's wrong: thread waiting for a lock is reported as being in the method woth lock, and its total run time is correct.
Could you please privatelly send me your Program.Main()?
I am interested when do you create threads (especially "Network") and when do you create UI thread (Application.Run?).
BTW, have you tried some other profilers, what do they show?
I've sent you an email with some of the relevant source code. We don't actually have an UI thread (it's a console app).
As for other profilers - no, I didn't try any other. I'll probably get to it today and shall report the results.
I tried to reproduce your scenario with multiple threads and start profiling not from very beginning.
But I haven't got anything strange in the snapshot.
I have sent you my test application by mail.
WRB, Ivan Shakhov