[U-Boot] [PATCH 06/13] log: Add an implemention of logging

[Simon Glass <sjg@chromium.org>]

Hi Masahiro,

On 27 September 2017 at 11:11, Masahiro Yamada
<yamada.masahiro@socionext.com> wrote:
> Hi Simon,
>
>
> 2017-09-27 4:10 GMT+09:00 Simon Glass <sjg@chromium.org>:
>> Hi Masahiro,
>>
>> On 20 September 2017 at 11:19, Masahiro Yamada
>> <yamada.masahiro@socionext.com> wrote:
>>> Hi Simon,
>>>
>>>
>>> 2017-09-20 22:49 GMT+09:00 Simon Glass <sjg@chromium.org>:
>>>> Hi Masahiro,
>>>>
>>>> On 19 September 2017 at 20:51, Masahiro Yamada
>>>> <yamada.masahiro@socionext.com> wrote:
>>>>> Hi Simon,
>>>>>
>>>>>
>>>>> 2017-09-17 6:23 GMT+09:00 Simon Glass <sjg@chromium.org>:
>>>>>
>>>>>>
>>>>>> +menu "Logging"
>>>>>> +
>>>>>> +config LOG
>>>>>> +       bool "Enable logging support"
>>>>>> +       help
>>>>>> +         This enables support for logging of status and debug messages. These
>>>>>> +         can be displayed on the console, recorded in a memory buffer, or
>>>>>> +         discarded if not needed. Logging supports various categories and
>>>>>> +         levels of severity.
>>>>>> +
>>>>>> +config SPL_LOG
>>>>>> +       bool "Enable logging support in SPL"
>>>>>> +       help
>>>>>> +         This enables support for logging of status and debug messages. These
>>>>>> +         can be displayed on the console, recorded in a memory buffer, or
>>>>>> +         discarded if not needed. Logging supports various categories and
>>>>>> +         levels of severity.
>>>>>
>>>>>
>>>>> Please note CONFIG_IS_ENABLED(LOG) is never enabled for TPL_BUILD.
>>>>>
>>>>> Since commit f1c6e1922eb57f4a212c09709801a1cc7920ffa9,
>>>>> CONFIG_IS_ENABLED(LOG) is expanded to CONFIG_TPL_LOG
>>>>> when building for TPL.
>>>>>
>>>>> Since that commit, if you add SPL_ prefixed option,
>>>>> you need to add a TPL_ one as well.
>>>>>
>>>>> I cannot believe why such a commit was accepted.
>>>>
>>>> Well either way is strange. it is strange that SPL is enabled for TPL
>>>> when really they are separate.
>>>>
>>>> We could revert that commit. But how do you think all of this SPL/TPL
>>>> control should actually work? What is intended?
>>>>
>>>> But I'm OK with not having logging in TPL until we need it.
>>>
>>> I will explain it in another mail.
>>>
>>>
>>>>>
>>>>>
>>>>>
>>>>>
>>>>>> +config LOG_MAX_LEVEL
>>>>>> +       int "Maximum log level to record"
>>>>>> +       depends on LOG
>>>>>> +       default 5
>>>>>> +       help
>>>>>> +         This selects the maximum log level that will be recorded. Any value
>>>>>> +         higher than this will be ignored. If possible log statements below
>>>>>> +         this level will be discarded at build time. Levels:
>>>>>> +
>>>>>> +           0 - panic
>>>>>> +           1 - critical
>>>>>> +           2 - error
>>>>>> +           3 - warning
>>>>>> +           4 - note
>>>>>> +           5 - info
>>>>>> +           6 - detail
>>>>>> +           7 - debug
>>>>>
>>>>>
>>>>> Please do not invent our own for U-Boot.
>>>>> Just use Linux log level.
>>>>>
>>>>>                         0 (KERN_EMERG)          system is unusable
>>>>>                         1 (KERN_ALERT)          action must be taken immediately
>>>>>                         2 (KERN_CRIT)           critical conditions
>>>>>                         3 (KERN_ERR)            error conditions
>>>>>                         4 (KERN_WARNING)        warning conditions
>>>>>                         5 (KERN_NOTICE)         normal but significant condition
>>>>>                         6 (KERN_INFO)           informational
>>>>>                         7 (KERN_DEBUG)          debug-level messages
>>>>
>>>> Yes I looked hard at that. The first three seem hard to distinguish in
>>>> U-Boot, but we can keep them I suppose. But most of my problem is with
>>>> the last two. INFO is what I plan to use for normal printf() output.
>>>> DEBUG is obviously for debugging and often involves vaste amounts of
>>>> stuff (e.g. logging every access to an MMC peripheral). We need
>>>> something in between. It could list the accesses to device at a high
>>>> level (e.g API calls) but not every little register access.
>>>>
>>>> So I don't think the Linux levels are suitable at the high end. We
>>>> could go up to 8 I suppose, instead of trying to save one at the
>>>> bottom?
>>>
>>>
>>> In fact, Linux has one more for debug.
>>>  dev_vdbg() is widely used in Linux.
>>>
>>> If you like, we can add one more level:
>>>
>>>                          8 (KERN_VDEBUG)           verbose debug messages
>>>
>>>
>>> Perhaps, logging every access to an MMC peripheral
>>> might belong to the vdbg level.
>>
>> I like the idea of having a log level for message contents (bytes) and
>> another for I/O access. So I will add two more in v2.
>>
>>>
>>>
>>>
>>> BTW, what do you mean "INFO is what I plan to use for normal printf() output"
>>>
>>> Is that mean printf() is equivalent to pr_info()?
>>> If loglevel is 6 or smaller, will all print() be silent?
>>> If so, probably we can not use command line interface.
>>
>> I mean that I want to (later) add a feature that logs normal printf()
>> output. If the console is silent then it would still be logged. Maybe
>> one day log functions will be used instead of printf(), but for now
>> this provides a useful way to make things wok.
>
>
> IMHO, printf() should be used for command line interface.

I suppose that makes sense, but in the interim we have a lot of
printf() stuff printing errors / messages.

>
> All SoC files, board files should use pr_*(),
> and drivers dev_*().

OK, for dev_*() we can generate the category automatically, but for
pr_*() we cannot. So those would just get the default category for the
file.

> I do not think we have much volume for notice or lower loglevel.

We have loads and loads of debug() things. If you mean that they will
normally be compiled out, yes. But I think we will see a trend to
adding more debugging into the code for when things go wrong. I'd like
to be able to do a 'debug' build and get all of that info recorded,
even if it is not displayed on the console.

>
> The categorization is useful for debug level
> and you can see the right thing to do
> for example, in drivers/i2c/Makefile of Linux.
>
> ccflags-$(CONFIG_I2C_DEBUG_CORE) := -DDEBUG

That is a build-time thing, though.

>
>
>
> This is already established in Linux
>
> [1] Create an entry for CONFIG_FOO_DEBUG in Kconfig
> [2] Add ccflags-$(CONFIG_FOO_DEBUG) := -DDEBUG
>
> You can do likewise for DM-core, EFI, or whatever.

That is not the (whole) use case for this log feature. Here you are
suggesting that we add an option to debug each uclass at run-time. I
think that might be quite useful to allow build-time control of what
categories are logged, but I think it is not a core feature needed
right now.

>
>
>
>
>> File filtering is useful I think in the interim, while nothing uses
>> categories. We can filter on particular files to pick out the messages
>> from those files. Even when we do have proper categories everywhere,
>> it might still be useful. I am not sure yet.
>
>
> File filter is pointless because we are generally
> supposed to add #define DEBUG to each file
> to make pr_dbg() effective.

With logging if you set the max level to DEBUG you don't need to do
that. You can filter at run-time.

Regards,
Simon