Hello,
pthread_cond_wait_1/2 [1] is rarely failing for me on 4.5.0-rc1,
on x86_64 KVM guest with 2 CPUs.
This test [1]:
- spawns 2 SCHED_RR threads
- first thread with higher priority sets alarm for 2 seconds and blocks on
condition
- second thread with lower priority is busy looping for 5 seconds
- after 2 seconds alarm signal arrives and handler signals condition
- high priority thread should resume running
But rarely I see that high priority thread doesn't resume running until
low priority thread completes its 5 second busy loop.
Looking at traces (short version attached, long version at [2]),
I see that after 2 seconds scheduler tries to wake up main thread, but it
appears to do that on same CPU where SCHED_RR low prio thread is running,
so nothing happens. Then scheduler makes numerous balance attempts,
but main thread is not balanced to idle CPU.
My guess is this started with following commit, which changed
weighted_cpuload():
commit b92486cbf2aa230d00f160664858495c81d2b37b
Author: Alex Shi <alex....@intel.com>
Date: Thu Jun 20 10:18:50 2013 +0800
sched: Compute runnable load avg in cpu_load and cpu_avg_load_per_task
I could reproduce it with HEAD set at above commit, I couldn't reproduce it
with 3.10 kernel so far.
Regards,
Jan
[1]
https://github.com/linux-test-project/ltp/blob/master/testcases/open_posix_testsuite/functional/threads/condvar/pthread_cond_wait_1.c
[2] http://jan.stancek.eu/tmp/pthread_cond_wait_failure/sched-trace1.tar.bz2
# test starts running
bash-5626 [001] .... 294.609021: sched_process_fork: comm=bash
pid=5626 child_comm=bash child_pid=10005
bash-5626 [001] d... 294.609023: sched_migrate_task: comm=bash
pid=10005 prio=120 orig_cpu=1 dest_cpu=0
bash-5626 [001] d... 294.609029: sched_wakeup_new: comm=bash
pid=10005 prio=120 target_cpu=000
<idle>-0 [000] d... 294.609073: sched_switch:
prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash
next_pid=10005 next_prio=120
condvar_pthread-10005 [000] d.h. 294.609355: sched_stat_runtime: comm=bash
pid=10005 runtime=330015 [ns] vruntime=937586860 [ns]
condvar_pthread-10005 [000] d... 294.610222: sched_stat_runtime:
comm=condvar_pthread pid=10005 runtime=866662 [ns] vruntime=938453522 [ns]
condvar_pthread-10005 [000] d... 294.610224: sched_migrate_task:
comm=condvar_pthread pid=10005 prio=120 orig_cpu=0 dest_cpu=0
condvar_pthread-10005 [000] .... 294.610231: sched_process_fork:
comm=condvar_pthread pid=10005 child_comm=condvar_pthread child_pid=10006
# high prio thread (10006) is started
condvar_pthread-10005 [000] d... 294.610232: sched_migrate_task:
comm=condvar_pthread pid=10006 prio=120 orig_cpu=0 dest_cpu=0
condvar_pthread-10005 [000] d... 294.610233: sched_stat_runtime:
comm=condvar_pthread pid=10005 runtime=11929 [ns] vruntime=938465451 [ns]
condvar_pthread-10005 [000] d... 294.610238: sched_wakeup_new:
comm=condvar_pthread pid=10006 prio=120 target_cpu=000
condvar_pthread-10005 [000] d... 294.610267: sched_stat_runtime:
comm=condvar_pthread pid=10005 runtime=34190 [ns] vruntime=938499641 [ns]
condvar_pthread-10005 [000] d... 294.610268: sched_migrate_task:
comm=condvar_pthread pid=10005 prio=120 orig_cpu=0 dest_cpu=0
condvar_pthread-10005 [000] .... 294.610270: sched_process_fork:
comm=condvar_pthread pid=10005 child_comm=condvar_pthread child_pid=10007
# low prio thread (10007) is started
condvar_pthread-10005 [000] d... 294.610271: sched_migrate_task:
comm=condvar_pthread pid=10007 prio=120 orig_cpu=0 dest_cpu=1
condvar_pthread-10005 [000] d... 294.610277: sched_wakeup_new:
comm=condvar_pthread pid=10007 prio=120 target_cpu=001
condvar_pthread-10005 [000] d... 294.610298: sched_stat_runtime:
comm=condvar_pthread pid=10005 runtime=31353 [ns] vruntime=938530994 [ns]
condvar_pthread-10005 [000] d... 294.610302: sched_switch:
prev_comm=condvar_pthread prev_pid=10005 prev_prio=120 prev_state=S ==>
next_comm=condvar_pthread next_pid=10006 next_prio=120
condvar_pthread-10006 [000] d... 294.610311: sched_stat_runtime:
comm=condvar_pthread pid=10006 runtime=12355 [ns] vruntime=944465872 [ns]
<idle>-0 [001] d... 294.610318: sched_switch:
prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==>
next_comm=condvar_pthread next_pid=10007 next_prio=120
condvar_pthread-10007 [001] d... 294.610332: sched_stat_runtime:
comm=condvar_pthread pid=10007 runtime=59910 [ns] vruntime=581696119 [ns]
condvar_pthread-10006 [000] d... 294.610340: sched_switch:
prev_comm=condvar_pthread prev_pid=10006 prev_prio=89 prev_state=S ==>
next_comm=swapper/0 next_pid=0 next_prio=120
condvar_pthread-10007 [001] d... 296.571389: sched_switch:
prev_comm=condvar_pthread prev_pid=10007 prev_prio=94 prev_state=R ==>
next_comm=watchdog/1 next_pid=13 next_prio=0
watchdog/1-13 [001] d... 296.571393: sched_migrate_task:
comm=condvar_pthread pid=10007 prio=94 orig_cpu=1 dest_cpu=0
<idle>-0 [000] d... 296.571413: sched_switch:
prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==>
next_comm=condvar_pthread next_pid=10007 next_prio=94
# after 2 seconds, alarm signal tries to wake up main thread on same cpu where
low prio thread is running
condvar_pthread-10007 [000] d.h. 296.610352: sched_wakeup:
comm=condvar_pthread pid=10005 prio=120 target_cpu=000
condvar_pthread-10007 [000] d... 299.610446: sched_switch:
prev_comm=condvar_pthread prev_pid=10007 prev_prio=94 prev_state=x ==>
next_comm=tuned next_pid=1183 next_prio=120
xfsaild/dm-0-424 [000] d... 299.610582: sched_switch:
prev_comm=xfsaild/dm-0 prev_pid=424 prev_prio=120 prev_state=S ==>
next_comm=condvar_pthread next_pid=10005 next_prio=120
# main thread runs only after low prio thread is done
condvar_pthread-10005 [000] dN.. 299.610596: sched_wakeup:
comm=condvar_pthread pid=10006 prio=89 target_cpu=000
condvar_pthread-10005 [000] dN.. 299.610597: sched_stat_runtime:
comm=condvar_pthread pid=10005 runtime=13944 [ns] vruntime=938544938 [ns]
condvar_pthread-10005 [000] d... 299.610598: sched_switch:
prev_comm=condvar_pthread prev_pid=10005 prev_prio=120 prev_state=R ==>
next_comm=condvar_pthread next_pid=10006 next_prio=89
condvar_pthread-10006 [000] d... 299.610614: sched_switch:
prev_comm=condvar_pthread prev_pid=10006 prev_prio=89 prev_state=x ==>
next_comm=condvar_pthread next_pid=10005 next_prio=120
condvar_pthread-10005 [000] d.h. 299.611591: sched_stat_runtime:
comm=condvar_pthread pid=10005 runtime=976745 [ns] vruntime=939521683 [ns]
condvar_pthread-10005 [000] d... 299.612029: sched_stat_runtime:
comm=condvar_pthread pid=10005 runtime=438310 [ns] vruntime=939959993 [ns]
condvar_pthread-10005 [000] d... 299.612031: sched_switch:
prev_comm=condvar_pthread prev_pid=10005 prev_prio=120 prev_state=x ==>
next_comm=rcuos/0 next_pid=9 next_prio=120
