A little side effect of the rt throttling

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Running on a 40 core box, I hit this nice latency while running
cyclictest on an idle box. The sched_rt_period_timer() grabbed locks
(I'm assuming the rq locks) 80 times!

      <idle>-0       0d..30  7151.231650: sched_switch:         swapper/0:0 [120] R ==> cyclictest:6178 [4]
    cyclicte-6178    0d.h20  7151.231651: funcgraph_entry:        0.051 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h40  7151.231663: hrtimer_cancel:       hrtimer=0xffffffff81bf4cd8
    cyclicte-6178    0d.h30  7151.231664: hrtimer_expire_entry: hrtimer=0xffffffff81bf4cd8 now=7153000011042  function=sched_rt_period_timer/0x0
    cyclicte-6178    0d.h20  7151.231667: funcgraph_entry:        0.050 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231668: funcgraph_entry:        0.043 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231668: funcgraph_entry:        0.075 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231668: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231669: funcgraph_entry:        4.008 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231673: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231674: funcgraph_entry:        0.082 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231674: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231674: funcgraph_entry:        0.081 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231675: funcgraph_entry:        0.049 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231675: funcgraph_entry:        0.761 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231677: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231677: funcgraph_entry:        0.099 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231678: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231682: funcgraph_entry:        0.081 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231682: funcgraph_entry:        0.049 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231682: funcgraph_entry:        0.103 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231683: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231683: funcgraph_entry:        0.083 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231683: funcgraph_entry:        0.049 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231686: funcgraph_entry:        0.182 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231692: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231693: funcgraph_entry:        0.165 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231694: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231694: funcgraph_entry:        7.818 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231703: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231704: funcgraph_entry:        6.887 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231714: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231720: funcgraph_entry:        0.171 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231722: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231723: funcgraph_entry:        1.654 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231725: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231726: funcgraph_entry:        0.177 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231727: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231727: funcgraph_entry:        0.170 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231731: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231731: funcgraph_entry:      + 11.838 us  |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231744: funcgraph_entry:        0.046 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231748: funcgraph_entry:        0.170 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231749: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231749: funcgraph_entry:        0.184 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231750: funcgraph_entry:        0.047 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231751: funcgraph_entry:        0.166 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231753: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231753: funcgraph_entry:        0.172 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231754: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231755: funcgraph_entry:        3.062 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231759: funcgraph_entry:        0.046 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231759: funcgraph_entry:        6.617 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231766: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231767: funcgraph_entry:        0.172 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231768: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231769: funcgraph_entry:        0.173 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231769: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231770: funcgraph_entry:        0.172 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231770: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231771: funcgraph_entry:        0.182 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231771: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231772: funcgraph_entry:        2.779 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231776: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231776: funcgraph_entry:        9.457 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231786: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231789: funcgraph_entry:        1.107 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231791: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231791: funcgraph_entry:        0.174 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231792: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231794: funcgraph_entry:        0.175 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231796: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231800: funcgraph_entry:      + 12.141 us  |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231812: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231814: funcgraph_entry:        0.173 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231816: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231817: funcgraph_entry:        0.175 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231817: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231818: funcgraph_entry:        0.175 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231819: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231819: funcgraph_entry:        0.944 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231821: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h20  7151.231821: funcgraph_entry:        0.175 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231823: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231824: hrtimer_expire_exit:  hrtimer=0xffffffff81bf4cd8
    cyclicte-6178    0d.h20  7151.231824: funcgraph_entry:        0.045 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h40  7151.231825: hrtimer_start:        hrtimer=0xffffffff81bf4cd8 function=sched_rt_period_timer expires=7154000000000 softexpires=7154000000000
    cyclicte-6178    0d.h40  7151.231825: hrtimer_cancel:       hrtimer=0xffff88103f80c4c0
    cyclicte-6178    0d.h30  7151.231826: hrtimer_expire_entry: hrtimer=0xffff88103f80c4c0 now=7153000011042
    cyclicte-6178    0d.h20  7151.231828: funcgraph_entry:        0.182 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231829: funcgraph_entry:        0.052 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h30  7151.231830: hrtimer_expire_exit:  hrtimer=0xffff88103f80c4c0
    cyclicte-6178    0d.h20  7151.231830: funcgraph_entry:        0.043 us   |  _raw_spin_lock();
    cyclicte-6178    0d.h40  7151.231831: hrtimer_start:        hrtimer=0xffff88103f80c4c0 function=tick_sched_timer expires=7153001000000 softexpires=7153001000000
    cyclicte-6178    0d..30  7151.231832: funcgraph_entry:        0.044 us   |  _raw_spin_lock_irqsave();

That function ran for 160 usecs! That function doesn't get called if you
disable the sched_rt_runtime_us (setting it to -1).

-- Steve


--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html


[Index of Archives]     [RT Stable]     [Kernel Newbies]     [IDE]     [Security]     [Git]     [Netfilter]     [Bugtraq]     [Yosemite]     [Yosemite News]     [MIPS Linux]     [ARM Linux]     [Linux Security]     [Linux RAID]     [Linux ATA RAID]     [Samba]     [Video 4 Linux]     [Device Mapper]

  Powered by Linux