printk and kernel log

printk and kernel log

[Kevin Wilson]

Hi,
When I add printk messages, and then try
to read /var/log/messages,
I see this:

Jun 24 03:43:06 localhost kernel: [ 1858.148661] in my_func1
Jun 24 03:44:03 localhost kernel: [ 1915.150953] in my_func2

What are the numbers is square brackets  ?  like [ 1858.148661]
or [ 1915.150953] ?

Is there a way I can get rid of them ?

Regards,
Kevin

printk and kernel log

[Augusto Mecking Caringi]

On Mon, Jun 24, 2013 at 6:49 AM, Kevin Wilson <wkevils@gmail.com> wrote:
> Hi,
> When I add printk messages, and then try
> to read /var/log/messages,
> I see this:
>
> Jun 24 03:43:06 localhost kernel: [ 1858.148661] in my_func1
> Jun 24 03:44:03 localhost kernel: [ 1915.150953] in my_func2
>
> What are the numbers is square brackets  ?  like [ 1858.148661]
> or [ 1915.150953] ?

Hi Kevin,

    This numbers are timestamps.

-- 
Augusto Mecking Caringi

printk and kernel log

[Alexandru Juncu]

On 25 June 2013 03:02, Augusto Mecking Caringi <augustocaringi@gmail.com> wrote:
> On Mon, Jun 24, 2013 at 6:49 AM, Kevin Wilson <wkevils@gmail.com> wrote:
>> Hi,
>> When I add printk messages, and then try
>> to read /var/log/messages,
>> I see this:
>>
>> Jun 24 03:43:06 localhost kernel: [ 1858.148661] in my_func1
>> Jun 24 03:44:03 localhost kernel: [ 1915.150953] in my_func2
>>
>> What are the numbers is square brackets  ?  like [ 1858.148661]
>> or [ 1915.150953] ?
>
> Hi Kevin,
>
>     This numbers are timestamps.


To add to Augusto's answer, they are number of seconds since the kernel booted.

printk and kernel log

[Mulyadi Santosa]

On Mon, Jun 24, 2013 at 4:49 PM, Kevin Wilson <wkevils@gmail.com> wrote:
> Hi,
> When I add printk messages, and then try
> to read /var/log/messages,
> I see this:
>
> Jun 24 03:43:06 localhost kernel: [ 1858.148661] in my_func1
> Jun 24 03:44:03 localhost kernel: [ 1915.150953] in my_func2
>
> What are the numbers is square brackets  ?  like [ 1858.148661]
> or [ 1915.150953] ?

IIRC, they are jiffies a.k.a timer clock. It is incremented every 1/HZ
second. Major distros usually use HZ=1000 these days.

Looking at kernel config, I believe this parameter is the one that
toggle that timestamp:
CONFIG_PRINTK_TIME=y

So changing it to N and recompile the kernel should get rid of it.

-- 
regards,

Mulyadi Santosa
Freelance Linux trainer and consultant

blog: the-hydra.blogspot.com
training: mulyaditraining.blogspot.com

printk and kernel log

[Kevin Wilson]

Hi,
You are right, thanks!
disabling CONFIG_PRINTK_TIME prevented this timestamps.

I believe they should have provide some sysfs entry for this, sorry
they did not do so

regards,
Kevin






On Tue, Jun 25, 2013 at 10:05 AM, Mulyadi Santosa
<mulyadi.santosa@gmail.com> wrote:
> On Mon, Jun 24, 2013 at 4:49 PM, Kevin Wilson <wkevils@gmail.com> wrote:
>> Hi,
>> When I add printk messages, and then try
>> to read /var/log/messages,
>> I see this:
>>
>> Jun 24 03:43:06 localhost kernel: [ 1858.148661] in my_func1
>> Jun 24 03:44:03 localhost kernel: [ 1915.150953] in my_func2
>>
>> What are the numbers is square brackets  ?  like [ 1858.148661]
>> or [ 1915.150953] ?
>
> IIRC, they are jiffies a.k.a timer clock. It is incremented every 1/HZ
> second. Major distros usually use HZ=1000 these days.
>
> Looking at kernel config, I believe this parameter is the one that
> toggle that timestamp:
> CONFIG_PRINTK_TIME=y
>
> So changing it to N and recompile the kernel should get rid of it.
>
> --
> regards,
>
> Mulyadi Santosa
> Freelance Linux trainer and consultant
>
> blog: the-hydra.blogspot.com
> training: mulyaditraining.blogspot.com

printk and kernel log

[Valdis.Kletnieks at vt.edu]

On Tue, 25 Jun 2013 12:04:08 +0300, Kevin Wilson said:
> Hi,
> You are right, thanks!
> disabling CONFIG_PRINTK_TIME prevented this timestamps.
>
> I believe they should have provide some sysfs entry for this, sorry
> they did not do so

Well actually, there's a boot-time cmdline parameter:

        printk.time=    Show timing data prefixed to each printk message line
                        Format: <bool>  (1/Y/y=enable, 0/N/n=disable)

And since the code that handles it treats it as a module parameter (even though
it's always builtin), you get this for free:

% ls -l /sys/module/printk/parameters
total 0
-rw-r--r--. 1 root root 4096 Jun 25 11:05 always_kmsg_dump
-rw-r--r--. 1 root root 4096 Jun 25 11:05 console_suspend
-rw-r--r--. 1 root root 4096 Jun 25 11:05 ignore_loglevel
-rw-r--r--. 1 root root 4096 Jun 25 11:05 time

So save yourselves the embarassment of submitting a patch to add it. ;)




-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 865 bytes
Desc: not available
Url : http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20130625/c5601f89/attachment.bin 

printk and kernel log

[Mulyadi Santosa]

On Tue, Jun 25, 2013 at 4:04 PM, Kevin Wilson <wkevils@gmail.com> wrote:
> Hi,
> You are right, thanks!
> disabling CONFIG_PRINTK_TIME prevented this timestamps.
>
> I believe they should have provide some sysfs entry for this, sorry
> they did not do so

Hey, you welcome :)

BTW, Valdis is right, I missed that boot parameter :))

-- 
regards,

Mulyadi Santosa
Freelance Linux trainer and consultant

blog: the-hydra.blogspot.com
training: mulyaditraining.blogspot.com

printk and kernel log

[Kevin Wilson]

Thanks!
One more question, if I may:
The kernel log says:
Jun 24 03:43:06 localhost kernel: [ 1858.148661] in my_func1

where is the "localhost" from ? the "hostname"  util does **not** show
localhost, by amd1. I am not sure, if remember well, there were
machines
on which the hostname appeared instead of localhost

rgs
Kevin


On Tue, Jun 25, 2013 at 6:07 PM,  <Valdis.Kletnieks@vt.edu> wrote:
> On Tue, 25 Jun 2013 12:04:08 +0300, Kevin Wilson said:
>> Hi,
>> You are right, thanks!
>> disabling CONFIG_PRINTK_TIME prevented this timestamps.
>>
>> I believe they should have provide some sysfs entry for this, sorry
>> they did not do so
>
> Well actually, there's a boot-time cmdline parameter:
>
>         printk.time=    Show timing data prefixed to each printk message line
>                         Format: <bool>  (1/Y/y=enable, 0/N/n=disable)
>
> And since the code that handles it treats it as a module parameter (even though
> it's always builtin), you get this for free:
>
> % ls -l /sys/module/printk/parameters
> total 0
> -rw-r--r--. 1 root root 4096 Jun 25 11:05 always_kmsg_dump
> -rw-r--r--. 1 root root 4096 Jun 25 11:05 console_suspend
> -rw-r--r--. 1 root root 4096 Jun 25 11:05 ignore_loglevel
> -rw-r--r--. 1 root root 4096 Jun 25 11:05 time
>
> So save yourselves the embarassment of submitting a patch to add it. ;)
>
>
>
>

printk and kernel log

[Valdis.Kletnieks at vt.edu]

On Thu, 27 Jun 2013 18:08:09 +0300, Kevin Wilson said:

> Jun 24 03:43:06 localhost kernel: [ 1858.148661] in my_func1
>
> where is the "localhost" from ?

That's added by your syslog daemon (whatever that might be). It's
basically the value returned by /bin/hostname

> machines on which the hostname appeared instead of localhost

That's because they had hostname set to something else, and you have it
set to 'localhost'

-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 865 bytes
Desc: not available
Url : http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20130627/8369e34c/attachment.bin 

printk and kernel log

[Kevin Wilson]

Thanks, but unfortuantely this is not so.
On this machine I have:
 /bin/hostname
amd1

Kevin

On Thu, Jun 27, 2013 at 6:37 PM,  <Valdis.Kletnieks@vt.edu> wrote:
> On Thu, 27 Jun 2013 18:08:09 +0300, Kevin Wilson said:
>
>> Jun 24 03:43:06 localhost kernel: [ 1858.148661] in my_func1
>>
>> where is the "localhost" from ?
>
> That's added by your syslog daemon (whatever that might be). It's
> basically the value returned by /bin/hostname
>
>> machines on which the hostname appeared instead of localhost
>
> That's because they had hostname set to something else, and you have it
> set to 'localhost'
>

printk and kernel log

[Valdis.Kletnieks at vt.edu]

On Thu, 27 Jun 2013 18:46:50 +0300, Kevin Wilson said:
> Thanks, but unfortuantely this is not so.
> On this machine I have:
>  /bin/hostname
> amd1

Weird.  Maybe you have a flaky syslog() call that writes UDP packets to the
local host, rather than using the unix-domain socket at /dev/log - when the
packet arrives, the syslogd gets the source address of the packet (which will
be 127.0.0.1), and looks it up (usually in /etc/hosts), where it's getting the
name "localhost".

If you want to fix that, change the entry in /etc/hosts (on my laptop,
it looks like this:

127.0.0.1   turing-police.cc.vt.edu localhost localhost.localdomain localhost4 localhost4.localdomain4
::1         turing-police.cc.vt.edu localhost localhost.localdomain localhost6 localhost6.localdomain6



-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 865 bytes
Desc: not available
Url : http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20130627/7809389c/attachment.bin