Message-ID: <CAFm5wm3JnwJpa2rqnNc9_n0-h1JfSDNvj+JO95k8UUgjnCHm_w@mail.gmail.com>
Date:	Fri, 3 Aug 2012 02:15:19 -0700
From:	"Pandita, Vikram" <vikram.pandita@...com>
To:	Kay Sievers <kay@...y.org>
Cc:	gregkh@...uxfoundation.org, linux-kernel@...r.kernel.org,
	Mike Turquette <mturquette@...aro.org>,
	Vimarsh Zutshi <vimarsh.zutshi@...il.com>
Subject: Re: [PATCH] printk: add option to print cpu id

Kay

On Thu, Aug 2, 2012 at 7:19 PM, Pandita, Vikram <vikram.pandita@...com> wrote:
> Kay
>
> On Thu, Aug 2, 2012 at 5:06 PM, Kay Sievers <kay@...y.org> wrote:
>> On Fri, Aug 3, 2012 at 1:50 AM, Pandita, Vikram <vikram.pandita@...com> wrote:
>>> On Thu, Aug 2, 2012 at 1:08 PM, Kay Sievers <kay@...y.org> 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@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Powered by blists - more mailing lists