Kernel traces coming back with trash/clutter

Kernel traces coming back with trash/clutter

[Mark Hull-Richter]

I am experimenting with the kernel (CentOSv4.4 x86_64, 2.6.9-42.0.10)
and I have added a number of traces in some relatively sensitive code
in the page cache and some i/o functions.

I am getting this odd content in the trace log (dmesg), and I cannot
figure out what it is or why it is there.

4296757675 pdflush(80): do_writepages: map>ops>wrtpgs ffffffffa0195ff5
4296757675 pdflush(80): mpage_writepages w/b index 49728 pages 256000
<7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
<7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
<7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
<7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
<7><7><7><7><7>__bio_add_page: 2x ph 88>=128 || hw 88>=88 || 360448>max
ffffffff802525d8 generic_make_request(bio 000001017c745300) 50729472, 704
__make_request(q 00000101b9293870, bio 000001017c745300: sdc; 50729600, 704)
ll_new_hw_segment: 70 + 29 > 88
<7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
<7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
<7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
<7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
<7><7><7><7>__bio_add_page: 2x ph 88>=128 || hw 88>=88 || 360448>max
ffffffff802525d8 generic_make_request(bio 000001017c745a80) 50730176, 704
__make_request(q 00000101b9293870, bio 000001017c745a80: sdc; 50730304, 704)
4296757684 swapper(0): dl_mv2dsp: sdc start 50710368 secs 1408

(The lines with the <7>s in them are long - I wrapped them for ease of
reading and to keep the width down somewhat.)

Any feedback that might illuminate this would be welcome.  Please CC
me personally as I am not yet able to subscribe to this list
(apologies).

Thanks.

--
Mark Hull-Richter, Linux Kernel Engineer
DATAllegro (www.datallegro.com)
85 Enterprise, Second Floor, Aliso Viejo, CA  92656
949-680-3082 - Office     949-330-7691 - fax

Re: Kernel traces coming back with trash/clutter

[John Anthony Kazos Jr.]

> I am experimenting with the kernel (CentOSv4.4 x86_64, 2.6.9-42.0.10)
> and I have added a number of traces in some relatively sensitive code
> in the page cache and some i/o functions.
> 
> I am getting this odd content in the trace log (dmesg), and I cannot
> figure out what it is or why it is there.
> 
> 4296757675 pdflush(80): do_writepages: map>ops>wrtpgs ffffffffa0195ff5
> 4296757675 pdflush(80): mpage_writepages w/b index 49728 pages 256000
> <7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
> <7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
> <7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
> <7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
> <7><7><7><7><7>__bio_add_page: 2x ph 88>=128 || hw 88>=88 || 360448>max
> ffffffff802525d8 generic_make_request(bio 000001017c745300) 50729472, 704
> __make_request(q 00000101b9293870, bio 000001017c745300: sdc; 50729600, 704)
> ll_new_hw_segment: 70 + 29 > 88
> <7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
> <7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
> <7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
> <7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
> <7><7><7><7>__bio_add_page: 2x ph 88>=128 || hw 88>=88 || 360448>max
> ffffffff802525d8 generic_make_request(bio 000001017c745a80) 50730176, 704
> __make_request(q 00000101b9293870, bio 000001017c745a80: sdc; 50730304, 704)
> 4296757684 swapper(0): dl_mv2dsp: sdc start 50710368 secs 1408
> 
> (The lines with the <7>s in them are long - I wrapped them for ease of
> reading and to keep the width down somewhat.)
> 
> Any feedback that might illuminate this would be welcome.  Please CC
> me personally as I am not yet able to subscribe to this list
> (apologies).

"<7>" is KERN_DEBUG in <include/linux/kernel.h>, used with printk. Are you 
using printk in the following forms?

printk(KERN_DEBUG "A debug message.\n");

...or...

const char msg_debug[] = KERN_DEBUG "A debug message.\n";
printk(msg_debug);

Perhaps you have something looping that's outputting KERN_DEBUG with a 
null message? Or one of your diagnostic printk statements includes 
KERN_DEBUG with no actual message?

Remember, if you have a string in a variable without a KERN_* 
prependation, you can do this.

printk(KERN_DEBUG "%s\n", debug_message);

Re: Kernel traces coming back with trash/clutter

[Mark Hull-Richter]

On 4/24/07, John Anthony Kazos Jr. <jakj@j-a-k-j.com> wrote:
> >
> > I am getting this odd content in the trace log (dmesg), and I cannot
> > figure out what it is or why it is there.
> >
> > <7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
> > <7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
> > <7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
> > <7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
> > <7><7><7><7><7>__bio_add_page: 2x ph 88>=128 || hw 88>=88 || 360448>max
> > ffffffff802525d8 generic_make_request(bio 000001017c745300) 50729472, 704
>
> "<7>" is KERN_DEBUG in <include/linux/kernel.h>, used with printk. Are you
> using printk in the following forms?
>
> printk(KERN_DEBUG "A debug message.\n");
>
Yes, exclusively.

> Perhaps you have something looping that's outputting KERN_DEBUG with a
> null message? Or one of your diagnostic printk statements includes
> KERN_DEBUG with no actual message?
>
No, they are all KERN_DEBUG<space>"some string here", almost all with
some formatted output as well.  Could I be overloading the printk
output buffer, as in possibly too tightly repeated/looped code to be
able to output it all?

> Remember, if you have a string in a variable without a KERN_*
> prependation, you can do this.
>
> printk(KERN_DEBUG "%s\n", debug_message);
>
Haven't tried that one - they're all of the form above.

Thanks again.

-- 
Mark Hull-Richter, Linux Kernel Engineer
DATAllegro (www.datallegro.com)
85 Enterprise, Second Floor, Aliso Viejo, CA  92656
949-680-3082 - Office     949-330-7691 - fax
[This message is NOT SPAM and is sent in strict accordance with
Google, Yahoo, AOL, Netscape and Earthlink Terms of Service.  If you
are NOT receiving this through a group and do not want any more emails
from me, please reply to me and let me know.  If you are receiving
this second-hand, this sender disclaims all responsibility for your
response.]

Re: Kernel traces coming back with trash/clutter

[John Anthony Kazos Jr.]

> > > I am getting this odd content in the trace log (dmesg), and I cannot
> > > figure out what it is or why it is there.
> > >
> > > <7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
> > > <7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
> > > <7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
> > > <7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7><7>
> > > <7><7><7><7><7>__bio_add_page: 2x ph 88>=128 || hw 88>=88 || 360448>max
> > > ffffffff802525d8 generic_make_request(bio 000001017c745300) 50729472, 704
> > 
> > Perhaps you have something looping that's outputting KERN_DEBUG with a
> > null message? Or one of your diagnostic printk statements includes
> > KERN_DEBUG with no actual message?
> > 
> No, they are all KERN_DEBUG<space>"some string here", almost all with
> some formatted output as well.  Could I be overloading the printk
> output buffer, as in possibly too tightly repeated/looped code to be
> able to output it all?

It is possible, I suppose. Is what you're working on open-source? If so, 
you could send it to me and I could try and reproduce it here and track it 
down. If you want me to, that is. (If you do send, please include a 
".config".)

Otherwise, I couldn't tell you what it might be. Make sure all your 
messages end with '\n', make sure you're not accidentally using the wrong 
formatting codes and it's backing over previous output with ^H or 
something. You could confirm or rule out the possibility of overflowing 
the printk buffers by writing a dummy module with a tight loop of nothing 
but printk statements with counters to see if you can get it to asplode.