Re: CONFIG_PRINTK_TIME woes

2005-08-23 Thread Tim Bird
Andrew Morton wrote: > Andrew Morton <[EMAIL PROTECTED]> wrote: > >>How about we give each arch a printk_clock()? > > > Which might be as simple as this.. > > > --- devel/kernel/printk.c~printk_clock2005-08-21 02:14:05.0 > -0700 > +++ devel-akpm/kernel/printk.c

Re: CONFIG_PRINTK_TIME woes

2005-08-23 Thread Tim Bird
Andrew Morton wrote: > Nick Piggin <[EMAIL PROTECTED]> wrote: >> >>What about just using jiffies, then? >> >>Really, sched_clock() is very broken for this (I know you're >>not arguing against that). >> >>It can go backwards when called twice from the same CPU, and the >>number returned by one CPU

Re: CONFIG_PRINTK_TIME woes

2005-08-23 Thread Nick Piggin
David S. Miller wrote: This is a useful feature, please do not labotomize it just because it's difficult to implement on ia64. Just make a "printk_get_timestamp_because_ia64_sucks()" interface or something like that :-) I was a bit unclear when I raised this issue. It is not just an ia64

RE: CONFIG_PRINTK_TIME woes

2005-08-23 Thread Luck, Tony
>I'd hate to have to test for something for CONFIG_PRINTK_TIME >every time sched_clock() is being called. Me too. >The quick fix would seem to be to only allow CONFIG_PRINTK_TIME >from kernel cmdline to make it happen a bit later. So basically >make int printk_time = 0 until command line is

Re: CONFIG_PRINTK_TIME woes

2005-08-23 Thread Tony Lindgren
* Andrew Morton <[EMAIL PROTECTED]> [050821 02:15]: > "Luck, Tony" <[EMAIL PROTECTED]> wrote: > > > > It has been pointed out to me that ia64 doesn't boot > > with CONFIG_PRINTK_TIME=y. The issue is the call to > > sched_clock() ... which on ia64 accesses some per-cpu > > data to adjust for

Re: CONFIG_PRINTK_TIME woes

2005-08-23 Thread Tony Lindgren
* Andrew Morton [EMAIL PROTECTED] [050821 02:15]: Luck, Tony [EMAIL PROTECTED] wrote: It has been pointed out to me that ia64 doesn't boot with CONFIG_PRINTK_TIME=y. The issue is the call to sched_clock() ... which on ia64 accesses some per-cpu data to adjust for possible variations in

RE: CONFIG_PRINTK_TIME woes

2005-08-23 Thread Luck, Tony
I'd hate to have to test for something for CONFIG_PRINTK_TIME every time sched_clock() is being called. Me too. The quick fix would seem to be to only allow CONFIG_PRINTK_TIME from kernel cmdline to make it happen a bit later. So basically make int printk_time = 0 until command line is

Re: CONFIG_PRINTK_TIME woes

2005-08-23 Thread Nick Piggin
David S. Miller wrote: This is a useful feature, please do not labotomize it just because it's difficult to implement on ia64. Just make a printk_get_timestamp_because_ia64_sucks() interface or something like that :-) I was a bit unclear when I raised this issue. It is not just an ia64

Re: CONFIG_PRINTK_TIME woes

2005-08-23 Thread Tim Bird
Andrew Morton wrote: Nick Piggin [EMAIL PROTECTED] wrote: What about just using jiffies, then? Really, sched_clock() is very broken for this (I know you're not arguing against that). It can go backwards when called twice from the same CPU, and the number returned by one CPU need have no

Re: CONFIG_PRINTK_TIME woes

2005-08-23 Thread Tim Bird
Andrew Morton wrote: Andrew Morton [EMAIL PROTECTED] wrote: How about we give each arch a printk_clock()? Which might be as simple as this.. --- devel/kernel/printk.c~printk_clock2005-08-21 02:14:05.0 -0700 +++ devel-akpm/kernel/printk.c2005-08-21

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread tony . luck
>Ah, thanks. Presumably it'll be considerably longer with %d's and %s's in >there. But still, ~10 usecs is good resolution for I/O operations. The variation in times from one call to the next seems to be greater than the time to evaluate 4 "%d" arguments. So we are back to how to get a

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread tony . luck
>How fast is printk? I haven't looked. > >ie: if you do back-to-back printk's, what's the timestamp increment? On ia64 it looks like about 4-5 usec increment for back-to-back printk (with no serial console configured, and dmesg -n to turn off messages to the VGA console). -Tony - To unsubscribe

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread Andrew Morton
[EMAIL PROTECTED] wrote: > > >How fast is printk? I haven't looked. > > > >ie: if you do back-to-back printk's, what's the timestamp increment? > > On ia64 it looks like about 4-5 usec increment for back-to-back > printk (with no serial console configured, and dmesg -n to turn > off messages to

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread tony . luck
>I turn off VC logging, and I turn off disk sync'ing, so it goes >straight to the page cache. > >I really do need sub-microsecond timings when I put a lot of >printk tracing into the stack. Right now you only have microsecond timing. Although printk() gets "nanosecond" resolution from

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread Andrew Morton
"David S. Miller" <[EMAIL PROTECTED]> wrote: > > I really do need sub-microsecond timings when I put a lot of > printk tracing into the stack. How fast is printk? I haven't looked. ie: if you do back-to-back printk's, what's the timestamp increment? - To unsubscribe from this list: send the

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread tony . luck
>> we go there ... I'd like to hear whether there are usage models that >> really need better resolution than jiffies can provide? > >I think so. Say you're debugging or performance tuning filesystem requests >and I/O completions, etc. You disable the console with `dmesg -n', run the >test

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread David S. Miller
From: Jason Uhlenkott <[EMAIL PROTECTED]> Date: Mon, 22 Aug 2005 13:33:06 -0700 > On Mon, Aug 22, 2005 at 01:20:52PM -0700, David S. Miller wrote: > > Not really, when I'm debugging TCP events over gigabit > > these timestamps are exceptionally handy. > > Yes, but how many of those figures are

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread Jason Uhlenkott
On Mon, Aug 22, 2005 at 01:20:52PM -0700, David S. Miller wrote: > From: [EMAIL PROTECTED] > Date: Mon, 22 Aug 2005 10:42:22 -0700 > > > At the other extreme ... the current use of sched_clock() with > > potentially nano-second resolution is way over the top. > > Not really, when I'm debugging

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread David S. Miller
From: [EMAIL PROTECTED] Date: Mon, 22 Aug 2005 10:42:22 -0700 > At the other extreme ... the current use of sched_clock() with > potentially nano-second resolution is way over the top. Not really, when I'm debugging TCP events over gigabit these timestamps are exceptionally handy. - To

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread Andrew Morton
[EMAIL PROTECTED] wrote: > > At the other extreme ... the current use of sched_clock() with > potentially nano-second resolution is way over the top. Logging > to a serial console at 115200 a typical line from printk will take > 2-4 milli-seconds to print ... so there would seem to be little >

RE: CONFIG_PRINTK_TIME woes

2005-08-22 Thread tony . luck
Andrew Morton wrote: >jiffies wouldn't have sufficient resolution for this application. Bear in >mind that this is just a debugging thing - it's better to have good >resolution with occasional theoretical weirdness than to have poor >resolution plus super-consistency, IMO. The majority of

RE: CONFIG_PRINTK_TIME woes

2005-08-22 Thread tony . luck
Andrew Morton wrote: jiffies wouldn't have sufficient resolution for this application. Bear in mind that this is just a debugging thing - it's better to have good resolution with occasional theoretical weirdness than to have poor resolution plus super-consistency, IMO. The majority of

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread Andrew Morton
[EMAIL PROTECTED] wrote: At the other extreme ... the current use of sched_clock() with potentially nano-second resolution is way over the top. Logging to a serial console at 115200 a typical line from printk will take 2-4 milli-seconds to print ... so there would seem to be little

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread David S. Miller
From: [EMAIL PROTECTED] Date: Mon, 22 Aug 2005 10:42:22 -0700 At the other extreme ... the current use of sched_clock() with potentially nano-second resolution is way over the top. Not really, when I'm debugging TCP events over gigabit these timestamps are exceptionally handy. - To unsubscribe

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread Jason Uhlenkott
On Mon, Aug 22, 2005 at 01:20:52PM -0700, David S. Miller wrote: From: [EMAIL PROTECTED] Date: Mon, 22 Aug 2005 10:42:22 -0700 At the other extreme ... the current use of sched_clock() with potentially nano-second resolution is way over the top. Not really, when I'm debugging TCP events

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread David S. Miller
From: Jason Uhlenkott [EMAIL PROTECTED] Date: Mon, 22 Aug 2005 13:33:06 -0700 On Mon, Aug 22, 2005 at 01:20:52PM -0700, David S. Miller wrote: Not really, when I'm debugging TCP events over gigabit these timestamps are exceptionally handy. Yes, but how many of those figures are really

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread tony . luck
we go there ... I'd like to hear whether there are usage models that really need better resolution than jiffies can provide? I think so. Say you're debugging or performance tuning filesystem requests and I/O completions, etc. You disable the console with `dmesg -n', run the test then do

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread Andrew Morton
David S. Miller [EMAIL PROTECTED] wrote: I really do need sub-microsecond timings when I put a lot of printk tracing into the stack. How fast is printk? I haven't looked. ie: if you do back-to-back printk's, what's the timestamp increment? - To unsubscribe from this list: send the line

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread tony . luck
I turn off VC logging, and I turn off disk sync'ing, so it goes straight to the page cache. I really do need sub-microsecond timings when I put a lot of printk tracing into the stack. Right now you only have microsecond timing. Although printk() gets nanosecond resolution from sched_clock() it

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread Andrew Morton
[EMAIL PROTECTED] wrote: How fast is printk? I haven't looked. ie: if you do back-to-back printk's, what's the timestamp increment? On ia64 it looks like about 4-5 usec increment for back-to-back printk (with no serial console configured, and dmesg -n to turn off messages to the VGA

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread tony . luck
How fast is printk? I haven't looked. ie: if you do back-to-back printk's, what's the timestamp increment? On ia64 it looks like about 4-5 usec increment for back-to-back printk (with no serial console configured, and dmesg -n to turn off messages to the VGA console). -Tony - To unsubscribe

Re: CONFIG_PRINTK_TIME woes

2005-08-22 Thread tony . luck
Ah, thanks. Presumably it'll be considerably longer with %d's and %s's in there. But still, ~10 usecs is good resolution for I/O operations. The variation in times from one call to the next seems to be greater than the time to evaluate 4 %d arguments. So we are back to how to get a timestamp

Re: CONFIG_PRINTK_TIME woes

2005-08-21 Thread Andrew Morton
Nick Piggin <[EMAIL PROTECTED]> wrote: > > Andrew Morton wrote: > > > > > yup. > > > > > >>Why not use something like do_gettimeofday? (or I'm sure one > >>of our time keepers can suggest the right thing to use). > > > > > > do_gettimeofday() takes locks, so a) we can't do printk from inside

Re: CONFIG_PRINTK_TIME woes

2005-08-21 Thread Nick Piggin
Andrew Morton wrote: yup. Why not use something like do_gettimeofday? (or I'm sure one of our time keepers can suggest the right thing to use). do_gettimeofday() takes locks, so a) we can't do printk from inside it and Dang, yeah maybe this is the showstopper. b) if you do a

Re: CONFIG_PRINTK_TIME woes

2005-08-21 Thread Andrew Morton
Nick Piggin <[EMAIL PROTECTED]> wrote: > > Andrew Morton wrote: > > Andrew Morton <[EMAIL PROTECTED]> wrote: > > > >>How about we give each arch a printk_clock()? > > > > > > Which might be as simple as this.. > > > > > > sched_clock() shouldn't really be taken outside kernel/sched.c, >

Re: CONFIG_PRINTK_TIME woes

2005-08-21 Thread Nick Piggin
Andrew Morton wrote: Andrew Morton <[EMAIL PROTECTED]> wrote: How about we give each arch a printk_clock()? Which might be as simple as this.. sched_clock() shouldn't really be taken outside kernel/sched.c, especially for things like this. It actually has some fundamental problems even

Re: CONFIG_PRINTK_TIME woes

2005-08-21 Thread Andrew Morton
Andrew Morton <[EMAIL PROTECTED]> wrote: > > How about we give each arch a printk_clock()? Which might be as simple as this.. --- devel/kernel/printk.c~printk_clock 2005-08-21 02:14:05.0 -0700 +++ devel-akpm/kernel/printk.c 2005-08-21 02:15:14.0 -0700 @@ -488,6 +488,11 @@

Re: CONFIG_PRINTK_TIME woes

2005-08-21 Thread Andrew Morton
"Luck, Tony" <[EMAIL PROTECTED]> wrote: > > It has been pointed out to me that ia64 doesn't boot > with CONFIG_PRINTK_TIME=y. The issue is the call to > sched_clock() ... which on ia64 accesses some per-cpu > data to adjust for possible variations in processor > speed between different cpus.

Re: CONFIG_PRINTK_TIME woes

2005-08-21 Thread Andrew Morton
Luck, Tony [EMAIL PROTECTED] wrote: It has been pointed out to me that ia64 doesn't boot with CONFIG_PRINTK_TIME=y. The issue is the call to sched_clock() ... which on ia64 accesses some per-cpu data to adjust for possible variations in processor speed between different cpus. Since the

Re: CONFIG_PRINTK_TIME woes

2005-08-21 Thread Andrew Morton
Andrew Morton [EMAIL PROTECTED] wrote: How about we give each arch a printk_clock()? Which might be as simple as this.. --- devel/kernel/printk.c~printk_clock 2005-08-21 02:14:05.0 -0700 +++ devel-akpm/kernel/printk.c 2005-08-21 02:15:14.0 -0700 @@ -488,6 +488,11 @@ static

Re: CONFIG_PRINTK_TIME woes

2005-08-21 Thread Nick Piggin
Andrew Morton wrote: Andrew Morton [EMAIL PROTECTED] wrote: How about we give each arch a printk_clock()? Which might be as simple as this.. sched_clock() shouldn't really be taken outside kernel/sched.c, especially for things like this. It actually has some fundamental problems even

Re: CONFIG_PRINTK_TIME woes

2005-08-21 Thread Andrew Morton
Nick Piggin [EMAIL PROTECTED] wrote: Andrew Morton wrote: Andrew Morton [EMAIL PROTECTED] wrote: How about we give each arch a printk_clock()? Which might be as simple as this.. sched_clock() shouldn't really be taken outside kernel/sched.c, especially for things like

Re: CONFIG_PRINTK_TIME woes

2005-08-21 Thread Nick Piggin
Andrew Morton wrote: yup. Why not use something like do_gettimeofday? (or I'm sure one of our time keepers can suggest the right thing to use). do_gettimeofday() takes locks, so a) we can't do printk from inside it and Dang, yeah maybe this is the showstopper. b) if you do a

Re: CONFIG_PRINTK_TIME woes

2005-08-21 Thread Andrew Morton
Nick Piggin [EMAIL PROTECTED] wrote: Andrew Morton wrote: yup. Why not use something like do_gettimeofday? (or I'm sure one of our time keepers can suggest the right thing to use). do_gettimeofday() takes locks, so a) we can't do printk from inside it and Dang, yeah