On 06/03/2014 10:46 AM, Gautham R Shenoy wrote: > On Mon, Jun 02, 2014 at 01:45:38PM +0530, Srivatsa S. Bhat wrote: >> On 06/02/2014 01:03 PM, Gautham R Shenoy wrote: >>> Hi, >>> >>> On Tue, May 27, 2014 at 02:23:38AM +0530, Srivatsa S. Bhat wrote: >>> >>> [..snip..] >>>> >>>> Experimental results: >>>> ==================== >>>> >>>> I ran a modified version of ebizzy (called 'sleeping-ebizzy') that sleeps >>>> in >>>> between its execution such that its total utilization can be a user-defined >>>> value, say 10% or 20% (higher the utilization specified, lesser the amount >>>> of >>>> sleeps injected). This ebizzy was run with a single-thread, tied to CPU 8. >>>> >>>> Behavior observed with tracing (sample taken from 40% utilization runs): >>>> ------------------------------------------------------------------------ >>>> >>>> Without patch: >>>> ~~~~~~~~~~~~~~ >>>> kworker/8:2-12137 416.335742: cpu_frequency: state=2061000 cpu_id=8 >>>> kworker/8:2-12137 416.335744: sched_switch: prev_comm=kworker/8:2 ==> >>>> next_comm=ebizzy >>>> <...>-40753 416.345741: sched_switch: prev_comm=ebizzy ==> >>>> next_comm=kworker/8:2 >>>> kworker/8:2-12137 416.345744: cpu_frequency: state=4123000 cpu_id=8 >>>> kworker/8:2-12137 416.345746: sched_switch: prev_comm=kworker/8:2 ==> >>>> next_comm=ebizzy >>>> <...>-40753 416.355738: sched_switch: prev_comm=ebizzy ==> >>>> next_comm=kworker/8:2 >>>> <snip> >>>> --------------------------------------------------------------------- >>>> <snip> >>>> <...>-40753 416.402202: sched_switch: prev_comm=ebizzy ==> >>>> next_comm=swapper/8 >>>> <idle>-0 416.502130: sched_switch: prev_comm=swapper/8 ==> >>>> next_comm=ebizzy >>>> <...>-40753 416.505738: sched_switch: prev_comm=ebizzy ==> >>>> next_comm=kworker/8:2 >>>> kworker/8:2-12137 416.505739: cpu_frequency: state=2061000 cpu_id=8 >>>> kworker/8:2-12137 416.505741: sched_switch: prev_comm=kworker/8:2 ==> >>>> next_comm=ebizzy >>>> <...>-40753 416.515739: sched_switch: prev_comm=ebizzy ==> >>>> next_comm=kworker/8:2 >>>> kworker/8:2-12137 416.515742: cpu_frequency: state=4123000 cpu_id=8 >>>> kworker/8:2-12137 416.515744: sched_switch: prev_comm=kworker/8:2 ==> >>>> next_comm=ebizzy >>>> >>>> Observation: Ebizzy went idle at 416.402202, and started running again at >>>> 416.502130. But cpufreq noticed the long idle period, and dropped the >>>> frequency >>>> at 416.505739, only to increase it back again at 416.515742, realizing >>>> that the >>>> workload is in-fact CPU bound. Thus ebizzy needlessly ran at the lowest >>>> frequency >>>> for almost 13 milliseconds (almost 1 full sample period), and this pattern >>>> repeats on every sleep-wakeup. This could hurt latency-sensitive workloads >>>> quite >>>> a lot. >>>> >>>> With patch: >>>> ~~~~~~~~~~~ >>>> >>>> kworker/8:2-29802 464.832535: cpu_frequency: state=2061000 cpu_id=8 >>>> <snip> >>>> --------------------------------------------------------------------- >>>> <snip> >>>> kworker/8:2-29802 464.962538: sched_switch: prev_comm=kworker/8:2 ==> >>>> next_comm=ebizzy >>>> <...>-40738 464.972533: sched_switch: prev_comm=ebizzy ==> >>>> next_comm=kworker/8:2 >>>> kworker/8:2-29802 464.972536: cpu_frequency: state=4123000 cpu_id=8 >>>> kworker/8:2-29802 464.972538: sched_switch: prev_comm=kworker/8:2 ==> >>>> next_comm=ebizzy >>>> <...>-40738 464.982531: sched_switch: prev_comm=ebizzy ==> >>>> next_comm=kworker/8:2 >>>> <snip> >>>> --------------------------------------------------------------------- >>>> <snip> >>>> kworker/8:2-29802 465.022533: sched_switch: prev_comm=kworker/8:2 ==> >>>> next_comm=ebizzy >>>> <...>-40738 465.032531: sched_switch: prev_comm=ebizzy ==> >>>> next_comm=kworker/8:2 >>>> kworker/8:2-29802 465.032532: sched_switch: prev_comm=kworker/8:2 ==> >>>> next_comm=ebizzy >>>> <...>-40738 465.035797: sched_switch: prev_comm=ebizzy ==> >>>> next_comm=swapper/8 >>>> <idle>-0 465.240178: sched_switch: prev_comm=swapper/8 ==> >>>> next_comm=ebizzy >>>> <...>-40738 465.242533: sched_switch: prev_comm=ebizzy ==> >>>> next_comm=kworker/8:2 >>>> kworker/8:2-29802 465.242535: sched_switch: prev_comm=kworker/8:2 ==> >>>> next_comm=ebizzy >>>> <...>-40738 465.252531: sched_switch: prev_comm=ebizzy ==> >>>> next_comm=kworker/8:2 >>>> >>> >>> Have the log entries emmitted by kworker/8 to report about the >>> cpu_frequency states been snipped out in the entries post the >>> "465.032531" mark ? >>> >> >> No, why? Anything looks odd at that point? > > I was expecting to see log messages of the following kind after a > kworker thread is scheduled in. > > "kworker/8:2-12137 416.505739: cpu_frequency: state=2061000 cpu_id=8" >
But this gets printed only if the frequency is changed. If the frequency is left at the same value as it was previously set at (that's the point of this patch), then we won't get this print. [Note that these logs are with the patch applied.] >> >> Note that the CPU went idle from 465.035797 to 465.240178, and hence >> cpufreq's >> deferrable timer didn't fire (and hence kworker didn't run). But once the CPU >> became busy again at 465.240178, the kworker got scheduled on the CPU within >> 2 ms (at 465.242533). > > Yes, but the logs don't show the frequency that the kworker thread > would have set on that cpu. > Yes, and that's expected, because we copy the previous load to the present interval, and hence kworker won't change the frequency (in most cases), because it finds that the frequency is already set suitably for the perceived load in this interval. Hence we don't see any prints in the logs indicating a change in frequency. Regards, Srivatsa S. Bhat -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
