[dpdk-dev] [RFC 0/8] eal: dynamic logs

[Wiles, Keith]

> On Feb 6, 2017, at 10:18 AM, Olivier Matz <olivier.matz at 6wind.com> wrote:
> 
> On Mon, 6 Feb 2017 15:55:20 +0000, "Wiles, Keith"
> <keith.wiles at intel.com> wrote:
>>> On Feb 6, 2017, at 9:27 AM, Olivier Matz <olivier.matz at 6wind.com>
>>> wrote:
>>> 
>>> On Mon, 6 Feb 2017 15:01:30 +0000, "Wiles, Keith"
>>> <keith.wiles at intel.com> wrote:  
>>>>> On Feb 6, 2017, at 8:10 AM, Olivier Matz <olivier.matz at 6wind.com>
>>>>> wrote:
>>>>> 
>>>>> Hi Bruce,
>>>>> 
>>>>> On Mon, 6 Feb 2017 13:49:03 +0000, Bruce Richardson
>>>>> <bruce.richardson at intel.com> wrote:    
>>>>>> On Mon, Feb 06, 2017 at 02:29:08PM +0100, Olivier Matz wrote:    
>>>>>>> The objective of this RFC patchset is to introduce a framework
>>>>>>> to support dynamic log types in EAL. It also provides one
>>>>>>> example of use (in i40e).
>>>>>>> 
>>>>>>> Features:
>>>>>>> - log types are identified by a string
>>>>>>> - at registration, a uniq identifier is associated to a log type
>>>>>>> - each log type can have its level changed dynamically
>>>>>>> - extend command line parameters to set the log level of a
>>>>>>> specific type, or logs matching a regular expression
>>>>>>> - keep compat with other legacy types (eal, malloc, ring, user*,
>>>>>>> etc... keep their hardcoded log type value)
>>>>>>> 
>>>>>>> At the end, when, we can expect that all non-dataplane logs are
>>>>>>> moved to be dynamic, so we can enable/disable them at runtime,
>>>>>>> without recompiling. Many debug options can probably be removed
>>>>>>> from configuration:
>>>>>>> $ git grep DEBUG config/common_base | wc -l
>>>>>>> 89
>>>>>>> 
>>>>>>> Comments are welcome!
>>>>>>> 
>>>>>> Initial scan through the patches this looks pretty good. However,
>>>>>> rather than continuing with our own logging system, have you
>>>>>> investigated what other tracing and logging systems might be out
>>>>>> there that we could possibly re-use? Could LTTng be a good fit
>>>>>> for DPDK, perhaps?    
>>>>> 
>>>>> I did not investigate much about existing logging system. I agree
>>>>> that could be a good alternative too.
>>>>> 
>>>>> On the other hand, I'm not really confident in adding a dependency
>>>>> to an external lib for a core component like eal. What if we
>>>>> deicide tomorrow to port dpdk to windows or any baremetal env?
>>>>> 
>>>>> Also, as far as I remember, the components that depend on external
>>>>> libraries are disabled today because we don't know how to properly
>>>>> manage the dependency (ex: pmd-pcap, vhost-numa, pmd-mlx, …).    
>>>> 
>>>> In a previous project I worked in we did not use log levels per say
>>>> for debugging code. We did have a couple general logging for misc
>>>> type logging.
>>>> 
>>>> When debugging you normally only need a couple files or functions
>>>> that need to produce logging output. In that case we defined
>>>> logging using the file and function as the key to determine if the
>>>> dynamic log messages are output. We use a string in the format of
>>>> "filename:function” we allowed for a wildcard to enable all
>>>> functions in a file or you can select a single function.
>>>> 
>>>> Using this type of logging for debugging a system is the most
>>>> useful if you just want general logging then we define something
>>>> similar to what we have today.  
>>> 
>>> I think the "filename:function" is not adequate if you are not the
>>> developer of that code. Example: you have a problem with a PMD, you
>>> just enable all logs for this PMD (or even all PMDs), you can check
>>> it and if you don't find the problem, you can send them on the ML
>>> for help. I think you don't care where the code is located.  
>> 
>> I do not understand your concern the design allows you to enable a
>> single file, which means all functions within a file “filename:*".
> 
> I think the user doesn't want to care about the file name of the C
> source.

The filename is just one way to isolate the logging output for debugging it needs to be easily defined/found. IMO 80% of debugging is locating and isolating the problem quickly and in most cases the output from a single or very small set of files even isolated to a small set of functions in those files is the best.

> 
> 
>> In
>> the case of the all PMDs it not the best way to debug as you get a
>> lot of output that may not be even related to the problem you are
>> trying to solve. The design does allow you to enable one or more PMDs
>> if say you are debugging say two PMDs. The output would be more
>> readable and less cluttered with output that is not germane to the
>> problem.
>> 
>> If I was debugging the TAP driver I would like to just enable
>> “rte_eth_tap_pmd.c:*” or maybe we can define a something registered
>> other then file name e.g. rte_log_register(“tap_pmd”); “tap_pmd:*” or
>> “tap_pmd:pmd_rx_burst” or “tap_pmd:rte_tap_pmd_probe”. We could for
>> the PMDs just use the PMD name we define at registration.
> 
> That's very similar to what is proposed in the patch...
> 
> See:
> 
> +	i40e_logtype_init = rte_log_register("pmd.i40e.init");
> 
> +	i40e_logtype_driver = rte_log_register("pmd.i40e.driver”);

These strings are just arbitrary strings unless you are forcing a format, which I did not see. The filename and function are constant strings I could easily determine as a developer. The problem with registering a string means I need to find that string or have a way to display all of the strings via a CLI.

The ‘:’ in the string is required in my suggestion and I would suggest the format of the string be defined, so the developer can wildcarding to enable messages. Requiring a format helps the developer and user to quickly locate the set of messages to log, the function level is just a clean way to isolate the logs again.

> 
> 
>> 
>> Maybe the register option brings us closer to the same goal, but add
>> the function or selecting a specific set functions. The design does
>> require a more active lookup at run time for dynamic debugging and we
>> would have to make sure if enabled it does not effect performance. We
>> used a hash table to locate the enabled debug log output.
> 
> Again, I don't really see the added value to be able enable logs on a
> per function basis. For users, it brings more complexity.

I really do not see you argument here as I am sure when debugging a function you add log messages in the function, which means you are most likely debugging that function.

Allowing the developers to selectively enable logging output in a CLI is very powerful and you can see this type of design in VPP and other systems.

Enabling a single or select set of functions allows the developer to remove all of the clutter and get only what they want, in some cases the log storage maybe limited or debugging over a serial line/internet to a remote location, ...

> 
> 
>> The design allowed us to use the command line or CLI to
>> enable/disable logging output.
> 
> Same with this proposal.

BTW, in your i40e example you do connect the logging debug to the CLI. Unless you meant something different.

I am not trying to argue here only wanting to make sure you address all of the reasons to have dynamic logging. I have not looked at the code in depth, but think it is close and needs to have a few stricter requirements we can enforce to make it simpler for developers to use.

Can the patch set be applied to a version of DPDK, so I can better understand your design?

Regards,
Keith