[ 11.333737] is this a ghost?

[ 11.333737] is this a ghost?

[Justin P. Mattock]

in dmesg I see:
[   11.333737]  
but nothing else.
          ---------------(cut)-----------------
[   11.247147] Monitor-Mwait will be used to enter C-1 state
[   11.247151] Monitor-Mwait will be used to enter C-2 state
[   11.247154] Monitor-Mwait will be used to enter C-3 state
[   11.247671] ACPI: CPU0 (power states: C1[C1] C2[C2] C3[C3])
[   11.247996] processor ACPI_CPU:00: registered as cooling_device0
[   11.248008] ACPI: Processor [CPU0] (supports 8 throttling states)
[   11.306465] ACPI: SSDT 3FEB8F10, 0087 (r1 APPLE   Cpu1Ist     3000
INTL 20050309)<7>power_supply ADP1: No power supply yet
[   11.306831] power_supply ADP1: power_supply_changed
[   11.306839] ACPI: AC Adapter [ADP1] (on-line)
[   11.333737]                         <------------what's with this!!!
[   11.342937] power_supply ADP1: power_supply_changed_work
[   11.351901] power_supply ADP1: power_supply_update_gen_leds 1
[   11.351916] ACPI: SSDT 3FEB7F10, 0085 (r1 APPLE   Cpu1Cst     3000
INTL 20050309)
[   11.357477] Marking TSC unstable due to TSC halts in idle
[   11.382273] power_supply ADP1: uevent
[   11.392955] power_supply ADP1: POWER_SUPPLY_NAME=ADP1
[   11.403674] power_supply ADP1: Static prop TYPE=Mains
[   11.413736] power_supply ADP1: 1 dynamic props
[   11.424526] power_supply ADP1: prop ONLINE=1
[   11.437151] ACPI: CPU1 (power states: C1[C1] C2[C2] C3[C3])

if you need to see the full dmesg I can attach..
I've seen this happen on a random.

regards;


-- 
Justin P. Mattock <justinmattock@gmail.com>

Re: [ 11.333737] is this a ghost?

[Alan Jenkins]

On 11/18/08, Justin P. Mattock <justinmattock@gmail.com> wrote:
> in dmesg I see:
> [   11.333737]
> but nothing else.
>           ---------------(cut)-----------------
> [   11.247147] Monitor-Mwait will be used to enter C-1 state
> [   11.247151] Monitor-Mwait will be used to enter C-2 state
> [   11.247154] Monitor-Mwait will be used to enter C-3 state
> [   11.247671] ACPI: CPU0 (power states: C1[C1] C2[C2] C3[C3])
> [   11.247996] processor ACPI_CPU:00: registered as cooling_device0
> [   11.248008] ACPI: Processor [CPU0] (supports 8 throttling states)
> [   11.306465] ACPI: SSDT 3FEB8F10, 0087 (r1 APPLE   Cpu1Ist     3000
> INTL 20050309)<7>power_supply ADP1: No power supply yet

Look at this last line.  The "<7>" is a priority marker.  Normally it
marks the start of a line, and should be hidden.  So you seem to be
missing a line break just after "20050309)"...

> [   11.306831] power_supply ADP1: power_supply_changed
> [   11.306839] ACPI: AC Adapter [ADP1] (on-line)
> [   11.333737]                         <------------what's with this!!!

...which seems to be delayed and reappears here?

> [   11.342937] power_supply ADP1: power_supply_changed_work
> [   11.351901] power_supply ADP1: power_supply_update_gen_leds 1
> [   11.351916] ACPI: SSDT 3FEB7F10, 0085 (r1 APPLE   Cpu1Cst     3000
> INTL 20050309)

> if you need to see the full dmesg I can attach..
> I've seen this happen on a random.

I guess you have a multicore processor (or some other sort of SMP), right?

I think kernel messages are not completely synchronized by design, for
reliability reasons.  (e.g. to make sure critical error messages /
backtraces can get through on a dying system).

Re: [ 11.333737] is this a ghost?

[Justin P. Mattock]

On Tue, 2008-11-18 at 11:15 +0000, Alan Jenkins wrote:
> On 11/18/08, Justin P. Mattock <justinmattock@gmail.com> wrote:
> > in dmesg I see:
> > [   11.333737]
> > but nothing else.
> >           ---------------(cut)-----------------
> > [   11.247147] Monitor-Mwait will be used to enter C-1 state
> > [   11.247151] Monitor-Mwait will be used to enter C-2 state
> > [   11.247154] Monitor-Mwait will be used to enter C-3 state
> > [   11.247671] ACPI: CPU0 (power states: C1[C1] C2[C2] C3[C3])
> > [   11.247996] processor ACPI_CPU:00: registered as cooling_device0
> > [   11.248008] ACPI: Processor [CPU0] (supports 8 throttling states)
> > [   11.306465] ACPI: SSDT 3FEB8F10, 0087 (r1 APPLE   Cpu1Ist     3000
> > INTL 20050309)<7>power_supply ADP1: No power supply yet
> 
> Look at this last line.  The "<7>" is a priority marker.  Normally it
> marks the start of a line, and should be hidden.  So you seem to be
> missing a line break just after "20050309)"...
> 
> > [   11.306831] power_supply ADP1: power_supply_changed
> > [   11.306839] ACPI: AC Adapter [ADP1] (on-line)
> > [   11.333737]                         <------------what's with this!!!
> 
> ...which seems to be delayed and reappears here?
> 
> > [   11.342937] power_supply ADP1: power_supply_changed_work
> > [   11.351901] power_supply ADP1: power_supply_update_gen_leds 1
> > [   11.351916] ACPI: SSDT 3FEB7F10, 0085 (r1 APPLE   Cpu1Cst     3000
> > INTL 20050309)
> 
> > if you need to see the full dmesg I can attach..
> > I've seen this happen on a random.
> 
> I guess you have a multicore processor (or some other sort of SMP), right?
> 
> I think kernel messages are not completely synchronized by design, for
> reliability reasons.  (e.g. to make sure critical error messages /
> backtraces can get through on a dying system).


Cool.
makes good sense to me, 
As long as it's not something that shouldn't be there,
or something that's broken. As for this happening again
looking at dmesg nothing, all synchronized.
Seems to randomly show itself.

regards;
  
-- 
Justin P. Mattock <justinmattock@gmail.com>

Re: [ 11.333737] is this a ghost?

[Alan Jenkins]

Justin P. Mattock wrote:
> On Tue, 2008-11-18 at 11:15 +0000, Alan Jenkins wrote:
>   
>> On 11/18/08, Justin P. Mattock <justinmattock@gmail.com> wrote:
>>     
>>> in dmesg I see:
>>> [   11.333737]
>>> but nothing else.
>>>           ---------------(cut)-----------------
>>> [   11.247147] Monitor-Mwait will be used to enter C-1 state
>>> [   11.247151] Monitor-Mwait will be used to enter C-2 state
>>> [   11.247154] Monitor-Mwait will be used to enter C-3 state
>>> [   11.247671] ACPI: CPU0 (power states: C1[C1] C2[C2] C3[C3])
>>> [   11.247996] processor ACPI_CPU:00: registered as cooling_device0
>>> [   11.248008] ACPI: Processor [CPU0] (supports 8 throttling states)
>>> [   11.306465] ACPI: SSDT 3FEB8F10, 0087 (r1 APPLE   Cpu1Ist     3000
>>> INTL 20050309)<7>power_supply ADP1: No power supply yet
>>>       
>> Look at this last line.  The "<7>" is a priority marker.  Normally it
>> marks the start of a line, and should be hidden.  So you seem to be
>> missing a line break just after "20050309)"...
>>
>>     
>>> [   11.306831] power_supply ADP1: power_supply_changed
>>> [   11.306839] ACPI: AC Adapter [ADP1] (on-line)
>>> [   11.333737]                         <------------what's with this!!!
>>>       
>> ...which seems to be delayed and reappears here?
>>
>>     
>>> [   11.342937] power_supply ADP1: power_supply_changed_work
>>> [   11.351901] power_supply ADP1: power_supply_update_gen_leds 1
>>> [   11.351916] ACPI: SSDT 3FEB7F10, 0085 (r1 APPLE   Cpu1Cst     3000
>>> INTL 20050309)
>>>       
>>> if you need to see the full dmesg I can attach..
>>> I've seen this happen on a random.
>>>       
>> I guess you have a multicore processor (or some other sort of SMP), right?
>>
>> I think kernel messages are not completely synchronized by design, for
>> reliability reasons.  (e.g. to make sure critical error messages /
>> backtraces can get through on a dying system).
>>     
>
>
> Cool.
> makes good sense to me, 
> As long as it's not something that shouldn't be there,
> or something that's broken. As for this happening again
> looking at dmesg nothing, all synchronized.
> Seems to randomly show itself.
>   

It's the ACPICA OS abstraction layer - it splits every message into
multiple printk() calls.  Other subsystems don't do this... it probably
could and should be fixed.

drivers/acpi/utmisc.c:

    void ACPI_INTERNAL_VAR_XFACE
    acpi_ut_info(const char *module_name, u32 line_number, const char
    *format, ...)
    {
        va_list args;

        /*
         * Removed module_name, line_number, and acpica version, not needed
         * for info output
         */
        acpi_os_printf("ACPI: ");

        va_start(args, format);
        acpi_os_vprintf(format, args);
        acpi_os_printf("\n");
        va_end(args);
    }

The alternative is to use the preprocessor, i.e. macros and string
concatenation to generate a single printk().

Alan

Re: [ 11.333737] is this a ghost?

[Justin P. Mattock]

On Tue, 2008-11-18 at 16:58 +0000, Alan Jenkins wrote:
> Justin P. Mattock wrote:
> > On Tue, 2008-11-18 at 11:15 +0000, Alan Jenkins wrote:
> >   
> >> On 11/18/08, Justin P. Mattock <justinmattock@gmail.com> wrote:
> >>     
> >>> in dmesg I see:
> >>> [   11.333737]
> >>> but nothing else.
> >>>           ---------------(cut)-----------------
> >>> [   11.247147] Monitor-Mwait will be used to enter C-1 state
> >>> [   11.247151] Monitor-Mwait will be used to enter C-2 state
> >>> [   11.247154] Monitor-Mwait will be used to enter C-3 state
> >>> [   11.247671] ACPI: CPU0 (power states: C1[C1] C2[C2] C3[C3])
> >>> [   11.247996] processor ACPI_CPU:00: registered as cooling_device0
> >>> [   11.248008] ACPI: Processor [CPU0] (supports 8 throttling states)
> >>> [   11.306465] ACPI: SSDT 3FEB8F10, 0087 (r1 APPLE   Cpu1Ist     3000
> >>> INTL 20050309)<7>power_supply ADP1: No power supply yet
> >>>       
> >> Look at this last line.  The "<7>" is a priority marker.  Normally it
> >> marks the start of a line, and should be hidden.  So you seem to be
> >> missing a line break just after "20050309)"...
> >>
> >>     
> >>> [   11.306831] power_supply ADP1: power_supply_changed
> >>> [   11.306839] ACPI: AC Adapter [ADP1] (on-line)
> >>> [   11.333737]                         <------------what's with this!!!
> >>>       
> >> ...which seems to be delayed and reappears here?
> >>
> >>     
> >>> [   11.342937] power_supply ADP1: power_supply_changed_work
> >>> [   11.351901] power_supply ADP1: power_supply_update_gen_leds 1
> >>> [   11.351916] ACPI: SSDT 3FEB7F10, 0085 (r1 APPLE   Cpu1Cst     3000
> >>> INTL 20050309)
> >>>       
> >>> if you need to see the full dmesg I can attach..
> >>> I've seen this happen on a random.
> >>>       
> >> I guess you have a multicore processor (or some other sort of SMP), right?
> >>
> >> I think kernel messages are not completely synchronized by design, for
> >> reliability reasons.  (e.g. to make sure critical error messages /
> >> backtraces can get through on a dying system).
> >>     
> >
> >
> > Cool.
> > makes good sense to me, 
> > As long as it's not something that shouldn't be there,
> > or something that's broken. As for this happening again
> > looking at dmesg nothing, all synchronized.
> > Seems to randomly show itself.
> >   
> 
> It's the ACPICA OS abstraction layer - it splits every message into
> multiple printk() calls.  Other subsystems don't do this... it probably
> could and should be fixed.
> 
> drivers/acpi/utmisc.c:
> 
>     void ACPI_INTERNAL_VAR_XFACE
>     acpi_ut_info(const char *module_name, u32 line_number, const char
>     *format, ...)
>     {
>         va_list args;
> 
>         /*
>          * Removed module_name, line_number, and acpica version, not needed
>          * for info output
>          */
>         acpi_os_printf("ACPI: ");
> 
>         va_start(args, format);
>         acpi_os_vprintf(format, args);
>         acpi_os_printf("\n");
>         va_end(args);
>     }
> 
> The alternative is to use the preprocessor, i.e. macros and string
> concatenation to generate a single printk().
> 
> Alan

Maybe I'm missing a library or something.
The issue with this is the consistency.
one reboot I'll see it up higher in dmesg,
and then on another reboot nothing, then
maybe a few more reboots I'll see it down lower
in dmesg(like what I posted). As for fixing this
I'm not educated enough to go in and exactly know what
to change(one day hopefully, so I can contribute),
But I am willing to try a patch out to see if it resolves
the issue. 

regards;

-- 
Justin P. Mattock <justinmattock@gmail.com>

Re: [ 11.333737] is this a ghost?

[Alan Jenkins]

Justin P. Mattock wrote:
> On Tue, 2008-11-18 at 16:58 +0000, Alan Jenkins wrote:
>   
>> Justin P. Mattock wrote:
>>     
>>> On Tue, 2008-11-18 at 11:15 +0000, Alan Jenkins wrote:
>>>   
>>>       
>>>> On 11/18/08, Justin P. Mattock <justinmattock@gmail.com> wrote:
>>>>     
>>>>         
>>>>> in dmesg I see:
>>>>> [   11.333737]
>>>>> but nothing else.
>>>>>           ---------------(cut)-----------------
>>>>> [   11.247147] Monitor-Mwait will be used to enter C-1 state
>>>>> [   11.247151] Monitor-Mwait will be used to enter C-2 state
>>>>> [   11.247154] Monitor-Mwait will be used to enter C-3 state
>>>>> [   11.247671] ACPI: CPU0 (power states: C1[C1] C2[C2] C3[C3])
>>>>> [   11.247996] processor ACPI_CPU:00: registered as cooling_device0
>>>>> [   11.248008] ACPI: Processor [CPU0] (supports 8 throttling states)
>>>>> [   11.306465] ACPI: SSDT 3FEB8F10, 0087 (r1 APPLE   Cpu1Ist     3000
>>>>> INTL 20050309)<7>power_supply ADP1: No power supply yet
>>>>>       
>>>>>           
>>>> Look at this last line.  The "<7>" is a priority marker.  Normally it
>>>> marks the start of a line, and should be hidden.  So you seem to be
>>>> missing a line break just after "20050309)"...
>>>>
>>>>     
>>>>         
>>>>> [   11.306831] power_supply ADP1: power_supply_changed
>>>>> [   11.306839] ACPI: AC Adapter [ADP1] (on-line)
>>>>> [   11.333737]                         <------------what's with this!!!
>>>>>       
>>>>>           
>>>> ...which seems to be delayed and reappears here?
>>>>
>>>>     
>>>>         
>>>>> [   11.342937] power_supply ADP1: power_supply_changed_work
>>>>> [   11.351901] power_supply ADP1: power_supply_update_gen_leds 1
>>>>> [   11.351916] ACPI: SSDT 3FEB7F10, 0085 (r1 APPLE   Cpu1Cst     3000
>>>>> INTL 20050309)
>>>>>       
>>>>> if you need to see the full dmesg I can attach..
>>>>> I've seen this happen on a random.
>>>>>       
>>>>>           
>>>> I guess you have a multicore processor (or some other sort of SMP), right?
>>>>
>>>> I think kernel messages are not completely synchronized by design, for
>>>> reliability reasons.  (e.g. to make sure critical error messages /
>>>> backtraces can get through on a dying system).
>>>>     
>>>>         
>>> Cool.
>>> makes good sense to me, 
>>> As long as it's not something that shouldn't be there,
>>> or something that's broken. As for this happening again
>>> looking at dmesg nothing, all synchronized.
>>> Seems to randomly show itself.
>>>   
>>>       
>> It's the ACPICA OS abstraction layer - it splits every message into
>> multiple printk() calls.  Other subsystems don't do this... it probably
>> could and should be fixed.
>>
>> drivers/acpi/utmisc.c:
>>
>>     void ACPI_INTERNAL_VAR_XFACE
>>     acpi_ut_info(const char *module_name, u32 line_number, const char
>>     *format, ...)
>>     {
>>         va_list args;
>>
>>         /*
>>          * Removed module_name, line_number, and acpica version, not needed
>>          * for info output
>>          */
>>         acpi_os_printf("ACPI: ");
>>
>>         va_start(args, format);
>>         acpi_os_vprintf(format, args);
>>         acpi_os_printf("\n");
>>         va_end(args);
>>     }
>>
>> The alternative is to use the preprocessor, i.e. macros and string
>> concatenation to generate a single printk().
>>
>> Alan
>>     
>
> Maybe I'm missing a library or something.
> The issue with this is the consistency.
> one reboot I'll see it up higher in dmesg,
> and then on another reboot nothing, then
> maybe a few more reboots I'll see it down lower
> in dmesg(like what I posted). As for fixing this
> I'm not educated enough to go in and exactly know what
> to change(one day hopefully, so I can contribute),
> But I am willing to try a patch out to see if it resolves
> the issue.
>   

Right.  It's simple enough, I can write a patch.  Not sure what would be
most acceptable though.

Len, this sounds like a genuine bug.  Would you accept a patch changing
ACPI_INFO(()) etc. to use GNU-style variadic macros?

Thanks
Alan