flush_to_ldisc executing 2500 times a second ?

flush_to_ldisc executing 2500 times a second ?

[Dave Jones]

While poking at an unrelated bug, I came up with a perf
command line that showed something curious.

perf record -a -e workqueue:workqueue_execute_start sleep 1
perf trace

shows flush_to_ldisc being executed ~2500 times.
(http://codemonkey.org.uk/junk/flush_to_ldisc.txt)

Steve Rostedt gave me a tip about trace-cmd to get a backtrace,

trace-cmd record -e workqueue_queue_work -O stacktrace sleep 1

which yields thousands of ..

           sleep-17431 [000] 35746.452637: workqueue_queue_work: work struct=0xffff880113f2a2a0 function=flush_to_ldisc workqueue=0xffff88013f80cb68 req_cpu=0 cpu=0
           sleep-17431 [000] 35746.452638: kernel_stack:         <stack trace>
=> __queue_work (ffffffff81068c25)
=> delayed_work_timer_fn (ffffffff81068cc8)
=> run_timer_softirq (ffffffff8105e651)
=> __do_softirq (ffffffff810571af)
=> call_softirq (ffffffff8100bbdc)
=> do_softirq (ffffffff8100d358)
=> irq_exit (ffffffff81057366)
=> smp_apic_timer_interrupt (ffffffff81482b9e)

Which doesn't really tell me much.


At the time of the profiling, there's nothing being output on any tty's
(and the profiling tools are also silent during the actual profiling) so
I'm curious as to what's causing the flushing to be necessary.

Anyone have any ideas what's going on here ? or something further
I could dig into ?

This is with 2.6.37-rc4.

The only other machine I have to test on right now is running 2.6.34, which
doesn't exhibit this behaviour.  I'll try to narrow it down further tomorrow.

	Dave

Re: flush_to_ldisc executing 2500 times a second ?

[Jiri Olsa]

hi,

sorry for late reply, I just got back from vacation..
is this still an issue?

thanks,
jirka

On Tue, Nov 30, 2010 at 11:07:09PM -0500, Dave Jones wrote:
> While poking at an unrelated bug, I came up with a perf
> command line that showed something curious.
> 
> perf record -a -e workqueue:workqueue_execute_start sleep 1
> perf trace
> 
> shows flush_to_ldisc being executed ~2500 times.
> (http://codemonkey.org.uk/junk/flush_to_ldisc.txt)
> 
> Steve Rostedt gave me a tip about trace-cmd to get a backtrace,
> 
> trace-cmd record -e workqueue_queue_work -O stacktrace sleep 1
> 
> which yields thousands of ..
> 
>            sleep-17431 [000] 35746.452637: workqueue_queue_work: work struct=0xffff880113f2a2a0 function=flush_to_ldisc workqueue=0xffff88013f80cb68 req_cpu=0 cpu=0
>            sleep-17431 [000] 35746.452638: kernel_stack:         <stack trace>
> => __queue_work (ffffffff81068c25)
> => delayed_work_timer_fn (ffffffff81068cc8)
> => run_timer_softirq (ffffffff8105e651)
> => __do_softirq (ffffffff810571af)
> => call_softirq (ffffffff8100bbdc)
> => do_softirq (ffffffff8100d358)
> => irq_exit (ffffffff81057366)
> => smp_apic_timer_interrupt (ffffffff81482b9e)
> 
> Which doesn't really tell me much.
> 
> 
> At the time of the profiling, there's nothing being output on any tty's
> (and the profiling tools are also silent during the actual profiling) so
> I'm curious as to what's causing the flushing to be necessary.
> 
> Anyone have any ideas what's going on here ? or something further
> I could dig into ?
> 
> This is with 2.6.37-rc4.
> 
> The only other machine I have to test on right now is running 2.6.34, which
> doesn't exhibit this behaviour.  I'll try to narrow it down further tomorrow.
> 
> 	Dave
> 

Re: flush_to_ldisc executing 2500 times a second ?

[Dave Jones]

On Mon, Dec 20, 2010 at 04:11:24PM +0100, Jiri Olsa wrote:
 > hi,
 > 
 > sorry for late reply, I just got back from vacation..
 > is this still an issue?
 > 
 > thanks,
 > jirka
 
I poked at it a while, then went to bed.
The next morning with the same kernel, I couldn't reproduce it.
Hasn't happened again since. Weird.

	Dave