Re: [PATCH] printk: add option to print cpu id

From: Pandita, Vikram
Date: Fri Aug 03 2012 - 05:15:41 EST


Kay

On Thu, Aug 2, 2012 at 7:19 PM, Pandita, Vikram <vikram.pandita@xxxxxx> wrote:
> Kay
>
> On Thu, Aug 2, 2012 at 5:06 PM, Kay Sievers <kay@xxxxxxxx> wrote:
>> On Fri, Aug 3, 2012 at 1:50 AM, Pandita, Vikram <vikram.pandita@xxxxxx> wrote:
>>> On Thu, Aug 2, 2012 at 1:08 PM, Kay Sievers <kay@xxxxxxxx> wrote:
>>
>>>> How is that supposed to be useful?
>>>>
>>>> The prefix is added while exporting data from the kmsg buffer, which
>>>> is just the CPU that *reads* the data from the buffer, not the one
>>>> that has *written* the data it into it.
>>>
>>> I don't think so.
>>> I can see the backtrace of the printk() call looks like follows:
>>>
>>> print_cpuid
>>> print_prefix
>>> msg_print_text
>>> console_unlock
>>> vprint_emit
>>> printk
>>>
>>> Now this is a synchronous path, where in the buffer is getting filled
>>> with cpuid and timer info from the printk() calling context.
>>> So you should get the right CPU id with the trace - with the exception
>>> that i pointed out earlier for preemption.
>>>
>>>>
>>>> Do I miss anything here?
>>>
>>> This is my understanding of the printk framework.
>>> At least the print_time and print_cpuid seems to be happening
>>> synchronously wrt printk
>>
>> Printk is a store-and-forward-model, and it always was. There is no
>> guarantee at all, that the data is immediately flushed to the console
>> by the same CPU, it just happens to be in most cases. It's pretty
>> common though, that a different task is doing that work when it gets
>> the console lock, and that is not a matter of preemption, it's normal
>> and expected operation. The data which CPU has emitted the text is
>> just not available. It would need to be stored in the records, for
>> this to work.
>>
>> Your patch just prints the CPU that writes to the console, not
>> necessarily the one that has stored the data. I think the second one
>> is which is what you are looking for, but that is not what the patch
>> does.
>>
>
> I did not understand well the complexity of the console layer. Thanks
> for enlightenment :-)
> Would be nice if you have any suggestion to get this done the right way.
>
> First look i could guess this would do, but need to study further:
>
> @@ -1550,6 +1550,9 @@ asmlinkage int vprintk_emit(int facility, int level,
> NULL, 0, recursion_msg, printed_len);
> }
>
> + text_len = print_cpuid(text);
> + text += text_len;
> +
> /*
> * The printf needs to come first; we need the syslog
> * prefix which might be passed-in as a parameter.
> @@ -1582,6 +1585,13 @@ asmlinkage int vprintk_emit(int facility, int level,
> }
> }
>
> + /* Adjust for cpu-id string */
> + if (printk_cpuid) {
> + strncpy(text - 4, textbuf, 4);
> + text -= 4;
> + text_len += 4;
> + }
> +
> if (level == -1)
> level = default_message_loglevel;
>

Understand somewhat better now the logging mechanism.
The proposal above does not seem to be correct or complete.

Will post v2 patch, hopefully fixing now.

>
>
>> Also dmesg and syslog uses the same logic and would put-out all
>> entirely wrong CPU information with it, because the original
>> information is long gone.
>>
>> Kay
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/