On 2018-04-23 22:33, John Hening wrote:
|
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.0000.00056.003
21849.587844[0002] s java[7340/7338]0.0000.00056.001
21849.607838[0002] s java[7340/7338]0.0000.00019.994
21849.615836[0002] s java[7340/7338]0.0000.0007.998
...............................................................................................
21849.691834[0002] s java[7340/7338]0.0000.0004.000
21849.703837[0001] s java[7340/7338]0.0000.00038.330
21849.711838[0005] s java[7340/7338]0.0000.0000.000
21849.719834[0005] s java[7340/7338]0.0000.0007.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 :-)
Maybe your setup is broken in some way. But perhaps if you unfilter the
results it will make more sense.
2. The second issue is:
The excerpt from perf sched script
|
java 7340[002]21848.012360:sched:sched_wakeup:comm=java
pid=7511prio=120target_cpu=005
java 7340[002]21848.012375:sched:sched_wakeup:comm=java
pid=7511prio=120target_cpu=005
java 7340[002]21848.012391:sched:sched_wakeup:comm=java
pid=7511prio=120target_cpu=005
java 7340[002]21848.012406:sched:sched_wakeup:comm=java
pid=7511prio=120target_cpu=005
...................................................................................................
swapper 0[007]21848.012554:sched:sched_wakeup:comm=java
pid=7377prio=120target_cpu=007
swapper 0[007]21848.012554:sched:sched_wakeup:comm=java
pid=7377prio=120target_cpu=007
...................................................................................................
java 7340[002]21848.012555:sched:sched_wakeup:comm=java
pid=7511prio=120target_cpu=005
java
7377[007]21848.012582:sched:sched_stat_runtime:comm=java
pid=7377runtime=37420[ns]vruntime=1628300433237[ns]
java 7340[002]21848.012585:sched:sched_wakeup:comm=java
pid=7511prio=120target_cpu=005
java
7377[007]21848.012587:sched:sched_switch:prev_comm=java
prev_pid=7377prev_prio=120prev_state=S
==>next_comm=swapper/7next_pid=0next_prio=120
|
Why my server receives sched_wakup that looks like spurious wakeups?
What is a swapper?
When a cpu goes idle, it switches to the swapper (an idiosyncrasy). An
interrupt then wakes up the cpu, runs the TCP stack, which decides to
wake up your process. Those wakeups will be seen from any process which
happens to run; swapper is simply the task that runs when nothing needs
the cpu.
--
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 mechanical-sympathy+unsubscr...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
