ACPI acpi_processor_get_throttling_info taking excessive time?

DISCUSSION Mike Travis 3 participants 7 messages Apr 26, 2010 – Apr 27, 2010 ACPI

Share & tools

Mike Travis

author

2010-04-26 01:47 UTC #0 lore raw

Hi,

On our test machine that has 1664 processors, we've discovered that the function acpi_processor_get_throttling_info takes 10 minutes. It's estimated that with 4096 cpus, this will take over 25 minutes.

It seems that the acpi_processor_get_throttling_info serially queries each cpu with a "runon" function to extract the throttling states.

My question is can this be optimized to use the previous processor's throttling states? Would there be any reason to expect any of the processors to be different?

Another thought, if each processor needs to be queried, can the functions be run in parallel?

Each time I broke into this delay, this was the call stack:

   6.559522 (    0.000032)| Stack traceback for pid 16894
   6.559554 (    0.000032)| 0xffff8827fb4d8680    16894        1  1  358   R  0xffff8827fb4d8d10  modprobe
   6.559628 (    0.000074)|  ffff8827fb535ae0 0000000000000018 ffffffff81246665 ffff8ac700000004
   6.559694 (    0.000066)|  ffff8d21fc07d150 ffff8ac7fc2e8800 0000000000000000 ffff8ac7fc2e9550
   6.559771 (    0.000077)|  0000000000000000 ffff8827fb535cd8 ffffffff81235822 ffffffff8158ac76
   6.559837 (    0.000066)| Call Trace:
   6.559852 (    0.000015)| Inexact backtrace:
   6.559874 (    0.000022)|
   6.559879 (    0.000005)|  [<ffffffff81246665>] ? acpi_ns_delete_namespace_by_owner+0xb2/0xdb
   6.559944 (    0.000065)|  [<ffffffff81235822>] ? acpi_ds_terminate_control_method+0x74/0x102
   6.560008 (    0.000064)|  [<ffffffff8124a60f>] ? acpi_ps_parse_aml+0x246/0x3c9
   6.560061 (    0.000053)|  [<ffffffff81251e25>] ? acpi_ut_create_internal_object_dbg+0x18/0x79
   6.560129 (    0.000068)|  [<ffffffff8124be20>] ? acpi_ps_execute_method+0x229/0x331
   6.560194 (    0.000065)|  [<ffffffff81246851>] ? acpi_ns_evaluate+0x189/0x2bc
   6.560246 (    0.000052)|  [<ffffffff8124611c>] ? acpi_evaluate_object+0x15e/0x2a5
   6.560301 (    0.000055)|  [<ffffffff812513e8>] ? acpi_ut_update_ref_count+0x17f/0x1d6
   6.560386 (    0.000085)|  [<ffffffffa012e14c>] ? acpi_processor_get_throttling_info+0x202/0x6f9 [processor]
   6.560464 (    0.000078)|  [<ffffffffa0131c46>] ? acpi_processor_add+0x93a/0xa8c [processor]
   6.560528 (    0.000064)|  [<ffffffff8122b247>] ? acpi_device_probe+0x4e/0x179
   6.560580 (    0.000052)|  [<ffffffff8128cb28>] ? driver_probe_device+0xc8/0x2d0
   6.560633 (    0.000053)|  [<ffffffff8128cdc3>] ? __driver_attach+0x93/0xa0
   6.560682 (    0.000049)|  [<ffffffff8128cd30>] ? __driver_attach+0x0/0xa0
   6.560740 (    0.000058)|  [<ffffffff8128c158>] ? bus_for_each_dev+0x58/0x80
   6.560790 (    0.000050)|  [<ffffffff8128b945>] ? bus_add_driver+0x155/0x2b0
   6.560839 (    0.000049)|  [<ffffffffa00d0000>] ? acpi_processor_init+0x0/0x10e [processor]
   6.560902 (    0.000063)|  [<ffffffff8128d0d9>] ? driver_register+0x79/0x170
   6.560952 (    0.000050)|  [<ffffffffa00d0000>] ? acpi_processor_init+0x0/0x10e [processor]
   6.561015 (    0.000063)|  [<ffffffffa00d009a>] ? acpi_processor_init+0x9a/0x10e [processor]
   6.561079 (    0.000064)|  [<ffffffff81067325>] ? __blocking_notifier_call_chain+0x65/0x90
   6.561141 (    0.000062)|  [<ffffffff810001e5>] ? do_one_initcall+0x35/0x190
   6.561190 (    0.000049)|  [<ffffffff8107b514>] ? sys_init_module+0xe4/0x270
   6.561240 (    0.000050)|  [<ffffffff81002e7b>] ? system_call_fastpath+0x16/0x1b

Thanks,
Mike

Zhang Rui

2010-04-26 02:21 UTC #1 lore raw

Hi, Mike,

please attach the acpidump of this machine, together with full dmesg output after boot (you can use boot option log_buf_len=4M to save more boot logs).
BTW: it would be great if you can file a new bug report about this at
https://bugzilla.kernel.org/enter_bug.cgi?product=ACPI
and attach all the info there.

thanks,
rui

Quoted 58 lines · Mike Travis

Hi,

It seems that the acpi_processor_get_throttling_info serially queries each cpu with a "runon" function to extract the throttling states.

My question is can this be optimized to use the previous processor's throttling states? Would there be any reason to expect any of the processors to be different?

Another thought, if each processor needs to be queried, can the functions be run in parallel?

Each time I broke into this delay, this was the call stack:

    6.559522 (    0.000032)| Stack traceback for pid 16894
    6.559554 (    0.000032)| 0xffff8827fb4d8680    16894        1  1  358   R  0xffff8827fb4d8d10  modprobe
    6.559628 (    0.000074)|  ffff8827fb535ae0 0000000000000018 ffffffff81246665 ffff8ac700000004
    6.559694 (    0.000066)|  ffff8d21fc07d150 ffff8ac7fc2e8800 0000000000000000 ffff8ac7fc2e9550
    6.559771 (    0.000077)|  0000000000000000 ffff8827fb535cd8 ffffffff81235822 ffffffff8158ac76
    6.559837 (    0.000066)| Call Trace:
    6.559852 (    0.000015)| Inexact backtrace:
    6.559874 (    0.000022)|
    6.559879 (    0.000005)|  [<ffffffff81246665>] ? acpi_ns_delete_namespace_by_owner+0xb2/0xdb
    6.559944 (    0.000065)|  [<ffffffff81235822>] ? acpi_ds_terminate_control_method+0x74/0x102
    6.560008 (    0.000064)|  [<ffffffff8124a60f>] ? acpi_ps_parse_aml+0x246/0x3c9
    6.560061 (    0.000053)|  [<ffffffff81251e25>] ? acpi_ut_create_internal_object_dbg+0x18/0x79
    6.560129 (    0.000068)|  [<ffffffff8124be20>] ? acpi_ps_execute_method+0x229/0x331
    6.560194 (    0.000065)|  [<ffffffff81246851>] ? acpi_ns_evaluate+0x189/0x2bc
    6.560246 (    0.000052)|  [<ffffffff8124611c>] ? acpi_evaluate_object+0x15e/0x2a5
    6.560301 (    0.000055)|  [<ffffffff812513e8>] ? acpi_ut_update_ref_count+0x17f/0x1d6
    6.560386 (    0.000085)|  [<ffffffffa012e14c>] ? acpi_processor_get_throttling_info+0x202/0x6f9 [processor]
    6.560464 (    0.000078)|  [<ffffffffa0131c46>] ? acpi_processor_add+0x93a/0xa8c [processor]
    6.560528 (    0.000064)|  [<ffffffff8122b247>] ? acpi_device_probe+0x4e/0x179
    6.560580 (    0.000052)|  [<ffffffff8128cb28>] ? driver_probe_device+0xc8/0x2d0
    6.560633 (    0.000053)|  [<ffffffff8128cdc3>] ? __driver_attach+0x93/0xa0
    6.560682 (    0.000049)|  [<ffffffff8128cd30>] ? __driver_attach+0x0/0xa0
    6.560740 (    0.000058)|  [<ffffffff8128c158>] ? bus_for_each_dev+0x58/0x80
    6.560790 (    0.000050)|  [<ffffffff8128b945>] ? bus_add_driver+0x155/0x2b0
    6.560839 (    0.000049)|  [<ffffffffa00d0000>] ? acpi_processor_init+0x0/0x10e [processor]
    6.560902 (    0.000063)|  [<ffffffff8128d0d9>] ? driver_register+0x79/0x170
    6.560952 (    0.000050)|  [<ffffffffa00d0000>] ? acpi_processor_init+0x0/0x10e [processor]
    6.561015 (    0.000063)|  [<ffffffffa00d009a>] ? acpi_processor_init+0x9a/0x10e [processor]
    6.561079 (    0.000064)|  [<ffffffff81067325>] ? __blocking_notifier_call_chain+0x65/0x90
    6.561141 (    0.000062)|  [<ffffffff810001e5>] ? do_one_initcall+0x35/0x190
    6.561190 (    0.000049)|  [<ffffffff8107b514>] ? sys_init_module+0xe4/0x270
    6.561240 (    0.000050)|  [<ffffffff81002e7b>] ? system_call_fastpath+0x16/0x1b

Thanks,
Mike

--
To unsubscribe from this list: send the line "unsubscribe linux-acpi" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Mike Travis

author

2010-04-26 18:14 UTC #2 lore raw

Hi,

Thanks for the reply. I've added a new BZ:

	https://bugzilla.kernel.org/show_bug.cgi?id=15856

and attached the console output I collected from:

ignore_loglevel acpi.debug_layer=0x2800001f acpi.debug_level=0x00000027

This took almost an hour to boot so adding all flags would not be practical.

Thanks!
Mike

Quoted 73 lines · Zhang Rui

Hi, Mike,
please attach the acpidump of this machine, together with full dmesg output after boot (you can use boot option log_buf_len=4M to save more boot logs).
BTW: it would be great if you can file a new bug report about this at
https://bugzilla.kernel.org/enter_bug.cgi?product=ACPI
and attach all the info there.
thanks,
rui
Quoted 58 lines · Mike Travis
Hi,
On our test machine that has 1664 processors, we've discovered that the function acpi_processor_get_throttling_info takes 10 minutes. It's estimated that with 4096 cpus, this will take over 25 minutes.
It seems that the acpi_processor_get_throttling_info serially queries each cpu with a "runon" function to extract the throttling states.
My question is can this be optimized to use the previous processor's throttling states? Would there be any reason to expect any of the processors to be different?
Another thought, if each processor needs to be queried, can the functions be run in parallel?
Each time I broke into this delay, this was the call stack:
    6.559522 (    0.000032)| Stack traceback for pid 16894
    6.559554 (    0.000032)| 0xffff8827fb4d8680    16894        1  1  358   R  0xffff8827fb4d8d10  modprobe
    6.559628 (    0.000074)|  ffff8827fb535ae0 0000000000000018 ffffffff81246665 ffff8ac700000004
    6.559694 (    0.000066)|  ffff8d21fc07d150 ffff8ac7fc2e8800 0000000000000000 ffff8ac7fc2e9550
    6.559771 (    0.000077)|  0000000000000000 ffff8827fb535cd8 ffffffff81235822 ffffffff8158ac76
    6.559837 (    0.000066)| Call Trace:
    6.559852 (    0.000015)| Inexact backtrace:
    6.559874 (    0.000022)|
    6.559879 (    0.000005)|  [<ffffffff81246665>] ? acpi_ns_delete_namespace_by_owner+0xb2/0xdb
    6.559944 (    0.000065)|  [<ffffffff81235822>] ? acpi_ds_terminate_control_method+0x74/0x102
    6.560008 (    0.000064)|  [<ffffffff8124a60f>] ? acpi_ps_parse_aml+0x246/0x3c9
    6.560061 (    0.000053)|  [<ffffffff81251e25>] ? acpi_ut_create_internal_object_dbg+0x18/0x79
    6.560129 (    0.000068)|  [<ffffffff8124be20>] ? acpi_ps_execute_method+0x229/0x331
    6.560194 (    0.000065)|  [<ffffffff81246851>] ? acpi_ns_evaluate+0x189/0x2bc
    6.560246 (    0.000052)|  [<ffffffff8124611c>] ? acpi_evaluate_object+0x15e/0x2a5
    6.560301 (    0.000055)|  [<ffffffff812513e8>] ? acpi_ut_update_ref_count+0x17f/0x1d6
    6.560386 (    0.000085)|  [<ffffffffa012e14c>] ? acpi_processor_get_throttling_info+0x202/0x6f9 [processor]
    6.560464 (    0.000078)|  [<ffffffffa0131c46>] ? acpi_processor_add+0x93a/0xa8c [processor]
    6.560528 (    0.000064)|  [<ffffffff8122b247>] ? acpi_device_probe+0x4e/0x179
    6.560580 (    0.000052)|  [<ffffffff8128cb28>] ? driver_probe_device+0xc8/0x2d0
    6.560633 (    0.000053)|  [<ffffffff8128cdc3>] ? __driver_attach+0x93/0xa0
    6.560682 (    0.000049)|  [<ffffffff8128cd30>] ? __driver_attach+0x0/0xa0
    6.560740 (    0.000058)|  [<ffffffff8128c158>] ? bus_for_each_dev+0x58/0x80
    6.560790 (    0.000050)|  [<ffffffff8128b945>] ? bus_add_driver+0x155/0x2b0
    6.560839 (    0.000049)|  [<ffffffffa00d0000>] ? acpi_processor_init+0x0/0x10e [processor]
    6.560902 (    0.000063)|  [<ffffffff8128d0d9>] ? driver_register+0x79/0x170
    6.560952 (    0.000050)|  [<ffffffffa00d0000>] ? acpi_processor_init+0x0/0x10e [processor]
    6.561015 (    0.000063)|  [<ffffffffa00d009a>] ? acpi_processor_init+0x9a/0x10e [processor]
    6.561079 (    0.000064)|  [<ffffffff81067325>] ? __blocking_notifier_call_chain+0x65/0x90
    6.561141 (    0.000062)|  [<ffffffff810001e5>] ? do_one_initcall+0x35/0x190
    6.561190 (    0.000049)|  [<ffffffff8107b514>] ? sys_init_module+0xe4/0x270
    6.561240 (    0.000050)|  [<ffffffff81002e7b>] ? system_call_fastpath+0x16/0x1b
Thanks,
Mike
--
To unsubscribe from this list: send the line "unsubscribe linux-acpi" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Len Brown

reviewer

2010-04-27 07:05 UTC #3 lore raw

Quoted 10 lines

...I've added a new BZ:
	https://bugzilla.kernel.org/show_bug.cgi?id=15856
and attached the console output I collected from:
ignore_loglevel acpi.debug_layer=0x2800001f acpi.debug_level=0x00000027
This took almost an hour to boot so adding all flags would not be practical.

I don't see any attachments to that bug report.

CONFIG_ACPI_DEBUG=y with acpi.debug_layer=0x20000000 maxcpus=4 should do it.

Also, the output from acpidump.

thanks,
-Len Brown, Intel Open Source Technology Center

Mike Travis

author

2010-04-27 17:19 UTC #4 lore raw

Quoted 13 lines · Len Brown

Quoted 10 lines
...I've added a new BZ:
	https://bugzilla.kernel.org/show_bug.cgi?id=15856
and attached the console output I collected from:
ignore_loglevel acpi.debug_layer=0x2800001f acpi.debug_level=0x00000027
This took almost an hour to boot so adding all flags would not be practical.
I don't see any attachments to that bug report.

Quoted 8 lines

CONFIG_ACPI_DEBUG=y with acpi.debug_layer=0x20000000 maxcpus=4 should do it.
Also, the output from acpidump.
thanks,
-Len Brown, Intel Open Source Technology Center

Hmm, I wonder why it didn't get put in? It was a gzipped text file.

I'll add the above as soon as I get back on the system. I *think* this might be the relevant part. It repeats this sequence 1664 times:

 584.386705 (    0.000126)| [  282.565042] processor_core-0609 [00] processor_get_info    : Bus mastering arbitration control present
 584.485405 (    0.098700)| [  282.577452] processor_core-0686 [00] processor_get_info    : Processor [0:0]
 584.485498 (    0.000093)| [  282.585423] processor_core-0689 [00] processor_get_info    : No PBLK (NULL address)
 584.485585 (    0.000087)| [  282.594175] ACPI: Execute Method [\_SB_.C000._PDC] (Node ffff8b27fc070210)
 584.659625 (    0.174040)| [  282.705124] processor_throttling-1143 [00] processor_get_throttli: pblk_address[0x00000000] duty_offset[0] duty_width[0]
 584.659764 (    0.000139)| [  282.717472] ACPI: Execute Method [\_SB_.C000._PTC] (Node ffff89affb0811f0)
 584.659851 (    0.000087)| [  282.776192] ACPI: Execute Method [\_SB_.C000._TSS] (Node ffff8ae7fc0721f0)

 584.750913 (    0.091062)| [  282.887162] processor_throttling-0482 [00] processor_get_throttli: Found 8 throttling states
 584.751027 (    0.000114)| [  282.896661] processor_throttling-0502 [00] processor_get_throttli: Extracting state 0
 584.751116 (    0.000089)| [  282.905454] processor_throttling-0502 [00] processor_get_throttli: Extracting state 1
 584.751212 (    0.000096)| [  282.914245] processor_throttling-0502 [00] processor_get_throttli: Extracting state 2
 584.751300 (    0.000088)| [  282.923042] processor_throttling-0502 [00] processor_get_throttli: Extracting state 3
 584.858075 (    0.106775)| [  282.931843] processor_throttling-0502 [00] processor_get_throttli: Extracting state 4
 584.858178 (    0.000103)| [  282.940654] processor_throttling-0502 [00] processor_get_throttli: Extracting state 5
 584.858268 (    0.000090)| [  282.949441] processor_throttling-0502 [00] processor_get_throttli: Extracting state 6
 584.858369 (    0.000101)| [  282.958233] processor_throttling-0502 [00] processor_get_throttli: Extracting state 7
 584.858460 (    0.000091)| [  282.967170] ACPI: Execute Method [\_SB_.C000._TPC] (Node ffff8947fc0701f0)
 584.858551 (    0.000091)| [  283.026637] processor_throttling-1189 [00] processor_get_throttli: Found 8 throttling states
 584.858651 (    0.000100)| [  283.036188] processor_throttling-0845 [00] processor_get_throttli: Invalid throttling state, reset
 584.958958 (    0.100307)| [  283.046279] processor_throttling-0265 [00] processor_throttling_n: PreChange Event:target T-state of CPU 0 is T0
 584.959084 (    0.000126)| [  283.060729] processor_throttling-0275 [00] processor_throttling_n: PostChange Event:CPU 0 is switched to T0
 584.959193 (    0.000109)| [  283.071686] ACPI: processor limited to max C-state 1
 584.959262 (    0.000069)| [  283.077760] ACPI: Execute Method [\_SB_.C000._CST] (Node ffff8987fc09f1f0)
 584.959340 (    0.000078)| [  283.139369] Monitor-Mwait will be used to enter C-1 state
 585.043300 (    0.083960)| [  283.145718] Monitor-Mwait will be used to enter C-3 state
 585.043375 (    0.000075)| [  283.151796] processor_idle-0519 [00] processor_get_power_in: Found 2 power states

Mike Travis

author

2010-04-27 19:16 UTC #5 lore raw

Quoted 3 lines

Quoted 2 lines
Hmm, I wonder why it didn't get put in? It was a gzipped text file.

I must have missed this last time:

The content type gzipped text file is invalid. Valid types must be of the form foo/bar where foo is either application, audio, image, message, model, multipart, text, or video.

Mike Travis

author

2010-04-27 19:22 UTC #6 lore raw

Quoted 7 lines · Mike Travis

Quoted 3 lines
Quoted 2 lines
Hmm, I wonder why it didn't get put in? It was a gzipped text file.
I must have missed this last time:
The content type gzipped text file is invalid. Valid types must be of the form foo/bar where foo is either application, audio, image, message, model, multipart, text, or video.

Uh oh, problem.

I gzipped the acpidump but when attaching:

The file you are trying to attach is 2456 kilobytes (KB) in size. Non-patch attachments cannot be more than 1000 KB.
We recommend that you store your attachment elsewhere and then specify the URL to this file on the attachment creation page in the AttachURL field. Alternately, if your attachment is an image, you could convert it to a compressible format like JPG or PNG and try again.

I will copy it someplace and provide a pointer.