Hello,
1. I have a simple one-threaded tcp server written in Java. I try to
measure its receive-and-process-response latency. More preceisely, the
client sends (by loopback) the 128-bytes message with a timestamp in the
header. The server receives a message, reads a content byte by byte and
compute a difference between `now` and the timestamp from the header. The
difference is more or less 6μs.
Now, I am trying to make it faster.
But, firstly I would like to examine a scheduling issue. So, I've collected
results with:
perf sched record -p <PID> -- sleep 10
and then:
perf sched timehist -V
Excerpt from the result is presented below: (I've filtered it for my server
thread)
wait
time sch delay run time
time cpu task name [tid/pid] (msec)
(msec) (msec)
--------------- ------ --------- ------------------------------ ---------
--------- ---------
1849.531842 [0002] s java[7340/7338] 0.000
0.000 56.003
21849.587844 [0002] s java[7340/7338] 0.000
0.000 56.001
21849.607838 [0002] s java[7340/7338] 0.000
0.000 19.994
21849.615836 [0002] s java[7340/7338] 0.000
0.000 7.998
...............................................................................................
21849.691834 [0002] s java[7340/7338] 0.000
0.000 4.000
21849.703837 [0001] s java[7340/7338] 0.000
0.000 38.330
21849.711838 [0005] s java[7340/7338] 0.000
0.000 0.000
21849.719834 [0005] s java[7340/7338] 0.000
0.000 7.996
My question is:
How is it possible that wait_time is always zero? After all, it is
impossible. My CPU is multicore but there is a lot of processes (threads)
that needs CPU time. How to interpret that?
>From the other hand I am gonna to reduce CPU migration. Perhaps it will
help :-)
2. The second issue is:
The excerpt from perf sched script
java 7340 [002] 21848.012360: sched:sched_wakeup: comm=java
pid=7511 prio=120 target_cpu=005
java 7340 [002] 21848.012375: sched:sched_wakeup: comm=java
pid=7511 prio=120 target_cpu=005
java 7340 [002] 21848.012391: sched:sched_wakeup: comm=java
pid=7511 prio=120 target_cpu=005
java 7340 [002] 21848.012406: sched:sched_wakeup: comm=java
pid=7511 prio=120 target_cpu=005
...................................................................................................
swapper 0 [007] 21848.012554: sched:sched_wakeup: comm=java
pid=7377 prio=120 target_cpu=007
swapper 0 [007] 21848.012554: sched:sched_wakeup: comm=java
pid=7377 prio=120 target_cpu=007
...................................................................................................
java 7340 [002] 21848.012555: sched:sched_wakeup: comm=java
pid=7511 prio=120 target_cpu=005
java 7377 [007] 21848.012582: sched:sched_stat_runtime: comm=java
pid=7377 runtime=37420 [ns] vruntime=1628300433237 [ns]
java 7340 [002] 21848.012585: sched:sched_wakeup: comm=java
pid=7511 prio=120 target_cpu=005
java 7377 [007] 21848.012587: sched:sched_switch:
prev_comm=java prev_pid=7377 prev_prio=120 prev_state=S ==> next_comm=
swapper/7 next_pid=0 next_prio=120
Why my server receives sched_wakup that looks like spurious wakeups? What
is a swapper?
--
You received this message because you are subscribed to the Google Groups
"mechanical-sympathy" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
For more options, visit https://groups.google.com/d/optout.
