[dpdk-dev] Logging format and time stamping

[dpdk-dev] Logging format and time stamping

[Wiles, Keith]

Hi all,

One other area with logging is we do not time stamp our logs to the screen, which I feel is needed in some cases. The bigger area is figuring out where the log message came from and greping the code is a bit hard in some cases.

I would like to see more information in the log output with file and line number of the log message with the time stamp. e.g.

[timestamp] pid function_name(filename:line) logid: log message


[ timestamp ] pid   Function/file/line number           Lid: Log message 
[  14.039999] 49203 pkt_data_to_mbuf(pkt_mbufs.h:85)    FNET: Failed append to mbuf too much data.

- The time stamp is from gettimeofday seconds.usecs formatted. Using a relative time from application start.
- The pid is the process ID or logical core id in fixed %5d or some fixed width.
- Function/file/line number __func__(basename(__FILE__):__LINE__) using a fixed width like %30s does not work in all cases but most.
- The lid is the LOG ID used(PMD, EAL, …) and then the original log message.

The timestamp helps determine when the message was created, but could be turned off for normal use. The pid would be nice to know which thread or lcore created the message. The bigger one is the function/file/line is the one a would like to see most. Making some of the fields fixed length helps align the messages.

What are your thoughts here?

Regards,
Keith

Re: [dpdk-dev] Logging format and time stamping

[Stephen Hemminger]

On Tue, 19 Dec 2017 14:12:27 +0000
"Wiles, Keith" <keith.wiles@intel.com> wrote:

> Hi all,
> 
> One other area with logging is we do not time stamp our logs to the screen, which I feel is needed in some cases. The bigger area is figuring out where the log message came from and greping the code is a bit hard in some cases.
> 
> I would like to see more information in the log output with file and line number of the log message with the time stamp. e.g.
> 
> [timestamp] pid function_name(filename:line) logid: log message
> 
> 
> [ timestamp ] pid   Function/file/line number           Lid: Log message 
> [  14.039999] 49203 pkt_data_to_mbuf(pkt_mbufs.h:85)    FNET: Failed append to mbuf too much data.
> 
> - The time stamp is from gettimeofday seconds.usecs formatted. Using a relative time from application start.
> - The pid is the process ID or logical core id in fixed %5d or some fixed width.
> - Function/file/line number __func__(basename(__FILE__):__LINE__) using a fixed width like %30s does not work in all cases but most.
> - The lid is the LOG ID used(PMD, EAL, …) and then the original log message.
> 
> The timestamp helps determine when the message was created, but could be turned off for normal use. The pid would be nice to know which thread or lcore created the message. The bigger one is the function/file/line is the one a would like to see most. Making some of the fields fixed length helps align the messages.
> 
> What are your thoughts here?
> 
> Regards,
> Keith
> 

Syslog is where most real applications send their logging, and it already does
timestamping.

Re: [dpdk-dev] Logging format and time stamping

[Wiles, Keith]

> On Dec 19, 2017, at 9:44 AM, Stephen Hemminger <stephen@networkplumber.org> wrote:
> 
> On Tue, 19 Dec 2017 14:12:27 +0000
> "Wiles, Keith" <keith.wiles@intel.com> wrote:
> 
>> Hi all,
>> 
>> One other area with logging is we do not time stamp our logs to the screen, which I feel is needed in some cases. The bigger area is figuring out where the log message came from and greping the code is a bit hard in some cases.
>> 
>> I would like to see more information in the log output with file and line number of the log message with the time stamp. e.g.
>> 
>> [timestamp] pid function_name(filename:line) logid: log message
>> 
>> 
>> [ timestamp ] pid   Function/file/line number           Lid: Log message 
>> [  14.039999] 49203 pkt_data_to_mbuf(pkt_mbufs.h:85)    FNET: Failed append to mbuf too much data.
>> 
>> - The time stamp is from gettimeofday seconds.usecs formatted. Using a relative time from application start.
>> - The pid is the process ID or logical core id in fixed %5d or some fixed width.
>> - Function/file/line number __func__(basename(__FILE__):__LINE__) using a fixed width like %30s does not work in all cases but most.
>> - The lid is the LOG ID used(PMD, EAL, …) and then the original log message.
>> 
>> The timestamp helps determine when the message was created, but could be turned off for normal use. The pid would be nice to know which thread or lcore created the message. The bigger one is the function/file/line is the one a would like to see most. Making some of the fields fixed length helps align the messages.
>> 
>> What are your thoughts here?
>> 
>> Regards,
>> Keith
>> 
> 
> Syslog is where most real applications send their logging, and it already does
> timestamping.

Yes, I agree I forgot to add it was optional. The log messages currently go the screen for me and I still need to see the timestamp instead of looking in a log file.

Regards,
Keith

Re: [dpdk-dev] Logging format and time stamping

[Stephen Hemminger]

On Tue, 19 Dec 2017 15:51:09 +0000
"Wiles, Keith" <keith.wiles@intel.com> wrote:

> > On Dec 19, 2017, at 9:44 AM, Stephen Hemminger <stephen@networkplumber.org> wrote:
> > 
> > On Tue, 19 Dec 2017 14:12:27 +0000
> > "Wiles, Keith" <keith.wiles@intel.com> wrote:
> >   
> >> Hi all,
> >> 
> >> One other area with logging is we do not time stamp our logs to the screen, which I feel is needed in some cases. The bigger area is figuring out where the log message came from and greping the code is a bit hard in some cases.
> >> 
> >> I would like to see more information in the log output with file and line number of the log message with the time stamp. e.g.
> >> 
> >> [timestamp] pid function_name(filename:line) logid: log message
> >> 
> >> 
> >> [ timestamp ] pid   Function/file/line number           Lid: Log message 
> >> [  14.039999] 49203 pkt_data_to_mbuf(pkt_mbufs.h:85)    FNET: Failed append to mbuf too much data.
> >> 
> >> - The time stamp is from gettimeofday seconds.usecs formatted. Using a relative time from application start.
> >> - The pid is the process ID or logical core id in fixed %5d or some fixed width.
> >> - Function/file/line number __func__(basename(__FILE__):__LINE__) using a fixed width like %30s does not work in all cases but most.
> >> - The lid is the LOG ID used(PMD, EAL, …) and then the original log message.
> >> 
> >> The timestamp helps determine when the message was created, but could be turned off for normal use. The pid would be nice to know which thread or lcore created the message. The bigger one is the function/file/line is the one a would like to see most. Making some of the fields fixed length helps align the messages.
> >> 
> >> What are your thoughts here?
> >> 
> >> Regards,
> >> Keith
> >>   
> > 
> > Syslog is where most real applications send their logging, and it already does
> > timestamping.  
> 
> Yes, I agree I forgot to add it was optional. The log messages currently go the screen for me and I still need to see the timestamp instead of looking in a log file.
> 
> Regards,
> Keith
> 

Applications are also free to implement their own log output handler.
Why not do that if you need something special.

Re: [dpdk-dev] Logging format and time stamping

[Wiles, Keith]

> On Dec 19, 2017, at 10:01 AM, Stephen Hemminger <stephen@networkplumber.org> wrote:
> 
> On Tue, 19 Dec 2017 15:51:09 +0000
> "Wiles, Keith" <keith.wiles@intel.com> wrote:
> 
>>> On Dec 19, 2017, at 9:44 AM, Stephen Hemminger <stephen@networkplumber.org> wrote:
>>> 
>>> On Tue, 19 Dec 2017 14:12:27 +0000
>>> "Wiles, Keith" <keith.wiles@intel.com> wrote:
>>> 
>>>> Hi all,
>>>> 
>>>> One other area with logging is we do not time stamp our logs to the screen, which I feel is needed in some cases. The bigger area is figuring out where the log message came from and greping the code is a bit hard in some cases.
>>>> 
>>>> I would like to see more information in the log output with file and line number of the log message with the time stamp. e.g.
>>>> 
>>>> [timestamp] pid function_name(filename:line) logid: log message
>>>> 
>>>> 
>>>> [ timestamp ] pid   Function/file/line number           Lid: Log message 
>>>> [  14.039999] 49203 pkt_data_to_mbuf(pkt_mbufs.h:85)    FNET: Failed append to mbuf too much data.
>>>> 
>>>> - The time stamp is from gettimeofday seconds.usecs formatted. Using a relative time from application start.
>>>> - The pid is the process ID or logical core id in fixed %5d or some fixed width.
>>>> - Function/file/line number __func__(basename(__FILE__):__LINE__) using a fixed width like %30s does not work in all cases but most.
>>>> - The lid is the LOG ID used(PMD, EAL, …) and then the original log message.
>>>> 
>>>> The timestamp helps determine when the message was created, but could be turned off for normal use. The pid would be nice to know which thread or lcore created the message. The bigger one is the function/file/line is the one a would like to see most. Making some of the fields fixed length helps align the messages.
>>>> 
>>>> What are your thoughts here?
>>>> 
>>>> Regards,
>>>> Keith
>>>> 
>>> 
>>> Syslog is where most real applications send their logging, and it already does
>>> timestamping.  
>> 
>> Yes, I agree I forgot to add it was optional. The log messages currently go the screen for me and I still need to see the timestamp instead of looking in a log file.
>> 
>> Regards,
>> Keith
>> 
> 
> Applications are also free to implement their own log output handler.
> Why not do that if you need something special.

I think as a general rule the file/function/line are needed here. I do not think we allow them to do their own macros/functions to replace our macros/functions, right?

I could see us adding a callout for the developer to create his own log string and use our current logging routines as just an example for logging. A default example to preserve the current output, but one that allows the developer to use a number of our routines as helpers.

I guess the best approach is to change the logging code to do a callout in a couple places to allow the developer to add his log information, is that the best solution then? 

Regards,
Keith