Bug 116371

Summary: [ASUS T100/BYT/BSW regression]Intel_pstate driver init time is long with ignore_loglevel
Product: Power Management Reporter: tianye (yex.tian)
Component: intel_pstateAssignee: Chen Yu (yu.c.chen)
Status: CLOSED INVALID    
Severity: normal CC: aaron.lu, lenb, rjw
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 4.6-rc3 Subsystem:
Regression: Yes Bisected commit-id:
Attachments: dmesg with ignore_loglevel
t100_dmesg info
bsw dmesg info
avoid sync during cpufreq initialization

Description tianye 2016-04-15 09:43:01 UTC
Created attachment 212831 [details]
dmesg with ignore_loglevel

This is regression bug.
mainline 4.6.0-rc2 kernel is good.
mainline 4.6.0-rc3 is failed.

BYT-T T100 intel_pstate driver init time is long with ignore_loglevel.


Reproduce steps:
1. boot kernel with ignore_loglevel
2. dmesg |grep -E "initcall.*intel_pstate_init" |grep -Po "(?<=after )[[:digit:]]*"


test environment
BAY TRAIL T / T100 (Board T1)
Platform: Bay Trail T / T100TA
CPU: Atom Z3740 CPU core i5 (family 6, model 55, stepping 3)
Software
Linux distribution: Ubuntu 14.04 64 bits
Kernel mainline : 4.6.0-rc3
BIOS: T100TA.313
Comment 1 Len Brown 2016-04-18 23:19:11 UTC
[    1.958123] calling  intel_pstate_init+0x0/0x404 @ 1
[    1.958130] Intel P-state driver initializing.
[    2.054776] initcall intel_pstate_init+0x0/0x404 returned 0 after 94359 usecs
Comment 2 tianye 2016-04-25 06:17:30 UTC
This issue still exists on mainline kernel 4.6-rc5.
Comment 3 tianye 2016-04-25 06:19:11 UTC
[    1.978834] calling  intel_pstate_init+0x0/0x404 @ 1
[    2.080034] initcall intel_pstate_init+0x0/0x404 returned 0 after 97662 usecs
Comment 4 Chen Yu 2016-04-25 06:31:11 UTC
(In reply to tianye from comment #3)
> [    1.978834] calling  intel_pstate_init+0x0/0x404 @ 1
> [    2.080034] initcall intel_pstate_init+0x0/0x404 returned 0 after 97662
> usecs
I've tested on a Mac Pro 12 and it did not reproduce. Since it is a regression
between 4.6-rc2 and rc3, would you please help do a bisec?
Comment 5 tianye 2016-04-25 10:57:27 UTC
By bisect, shows the first bad commit is 3ce093d.

commit 3ce093d4de753d6c92cc09366e29d0618a62f542
Author:     Len Brown <len.brown@intel.com>
AuthorDate: Wed Apr 6 17:00:59 2016 -0400
Commit:     Rafael J. Wysocki <rafael.j.wysocki@intel.com>
CommitDate: Thu Apr 7 22:11:08 2016 +0200

    intel_idle: Add KBL support

    KBL is similar to SKL

    Signed-off-by: Len Brown <len.brown@intel.com>
    Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
Comment 6 Chen Yu 2016-04-25 11:25:17 UTC
(In reply to tianye from comment #5)
> By bisect, shows the first bad commit is 3ce093d.
> 
> commit 3ce093d4de753d6c92cc09366e29d0618a62f542
> Author:     Len Brown <len.brown@intel.com>
> AuthorDate: Wed Apr 6 17:00:59 2016 -0400
> Commit:     Rafael J. Wysocki <rafael.j.wysocki@intel.com>
> CommitDate: Thu Apr 7 22:11:08 2016 +0200
> 
>     intel_idle: Add KBL support
> 
>     KBL is similar to SKL
> 
>     Signed-off-by: Len Brown <len.brown@intel.com>
>     Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>

According to model number in the bootup dmesg:
family: 0x6, model: 0x37, stepping: 0x3, 
above patch should not be related to the regression, since it is a BYT.
Comment 7 Rafael J. Wysocki 2016-04-25 23:26:10 UTC
Here are intel_pstate commits merged between 4.6-rc2 and 4.6-rc3 that can make a difference:

30a3915385f1 cpufreq: intel_pstate: fix inconsistency in setting policy limits
febce40febcf intel_pstate: Avoid extra invocation of intel_pstate_sample()
bb6ab52f2bef intel_pstate: Do not set utilization update hook too early

@tianye: Can you please check these?
Comment 8 tianye 2016-04-26 04:07:30 UTC
Test these commit on BSW RVP:
Grub parameters: initcall_debug text no_console_suspend ignore_loglevel

commit: 30a3915385

 dmesg | grep intel_pstate
[    3.267886] calling  intel_pstate_init+0x0/0x4e1 @ 1
[    3.591804] initcall intel_pstate_init+0x0/0x4e1 returned 0 after 316430 usecs

commit: febce40fe  

[    3.564839] calling  intel_pstate_init+0x0/0x4e1 @ 1
[    3.593108] initcall intel_pstate_init+0x0/0x4e1 returned 0 after 23627 usecs

commit: bb6ab52f2

[    3.292365] calling  intel_pstate_init+0x0/0x4e1 @ 1
[    3.624169] initcall intel_pstate_init+0x0/0x4e1 returned 0 after 323833 usecs



------------------------------------

Test these commit on T100:
Grub parameters: initcall_debug text log_buf_len=4M no_console_suspend ignore_loglevel
commit: 30a3915385

 dmesg | grep intel_pstate
[    3.069437] calling  intel_pstate_init+0x0/0x4e1 @ 1
[    3.196149] initcall intel_pstate_init+0x0/0x4e1 returned 0 after 123715 usecs


commit: febce40fe 

dmesg | grep intel_pstate
[    3.367816] calling  intel_pstate_init+0x0/0x4e1 @ 1
[    3.499332] initcall intel_pstate_init+0x0/0x4e1 returned 0 after 128406 usecs

commit: bb6ab52f2

[    3.261449] calling  intel_pstate_init+0x0/0x4e1 @ 1
[    3.389161] initcall intel_pstate_init+0x0/0x4e1 returned 0 after 124690 usecs
Comment 9 tianye 2016-04-26 04:29:00 UTC
(In reply to tianye from comment #5)
> By bisect, shows the first bad commit is 3ce093d.
> 
> commit 3ce093d4de753d6c92cc09366e29d0618a62f542
> Author:     Len Brown <len.brown@intel.com>
> AuthorDate: Wed Apr 6 17:00:59 2016 -0400
> Commit:     Rafael J. Wysocki <rafael.j.wysocki@intel.com>
> CommitDate: Thu Apr 7 22:11:08 2016 +0200
> 
>     intel_idle: Add KBL support
> 
>     KBL is similar to SKL
> 
>     Signed-off-by: Len Brown <len.brown@intel.com>
>     Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>


Yesterday I pasted the commit(3ce093d4d) was the first bad commit's parents commit.

By bisect on BSW RVP, the first bad commit is fa81e66e.

commit fa81e66ec8648f62e96e95e53db2ea95a4b57b26
Merge: 9735a22 b318556 3ce093d 169b38373
Author:     Rafael J. Wysocki <rafael.j.wysocki@intel.com>
AuthorDate: Fri Apr 8 21:46:05 2016 +0200
Commit:     Rafael J. Wysocki <rafael.j.wysocki@intel.com>
CommitDate: Fri Apr 8 21:46:05 2016 +0200

    Merge branches 'pm-cpufreq', 'pm-cpuidle' and 'acpi-cppc'

    * pm-cpufreq:
      cpufreq: dt: Drop stale comment
      cpufreq: intel_pstate: Documenation for structures
      cpufreq: intel_pstate: fix inconsistency in setting policy limits
      intel_pstate: Avoid extra invocation of intel_pstate_sample()
      intel_pstate: Do not set utilization update hook too early

    * pm-cpuidle:
      intel_idle: Add KBL support
      intel_idle: Add SKX support
      intel_idle: Clean up all registered devices on exit.
      intel_idle: Propagate hot plug errors.
      intel_idle: Don't overreact to a cpuidle registration failure.
      intel_idle: Setup the timer broadcast only on successful driver load.
      intel_idle: Avoid a double free of the per-CPU data.
      intel_idle: Fix dangling registration on error path.
      intel_idle: Fix deallocation order on the driver exit path.
      intel_idle: Remove redundant initialization calls.
      intel_idle: Fix a helper function's return value.
      intel_idle: remove useless return from void function.

    * acpi-cppc:
      mailbox: pcc: Don't access an unmapped memory address space





commit: fa81e66

dmesg | grep intel_pstate
[    3.262791] calling  intel_pstate_init+0x0/0x4e1 @ 1
[    4.193930] initcall intel_pstate_init+0x0/0x4e1 returned 0 after 909308 usecs
Comment 10 Rafael J. Wysocki 2016-04-26 19:33:47 UTC
This is a merge commit, so it looks like the issue was introduced by a merge.  Now, in comment #8 you kind of confirmed that you see the problem with the pm-cpufreq branch alone, so the base of the merge seems to be problematic already.

What did you get in dmesg with 4.6-rc2?
Comment 11 Rafael J. Wysocki 2016-04-26 19:35:31 UTC
Also please check this commit: c75361c0b08a cpufreq: Make cpufreq_quick_get() safe to call
Comment 12 tianye 2016-04-27 03:27:25 UTC
Created attachment 214491 [details]
t100_dmesg info
Comment 13 tianye 2016-04-27 03:27:53 UTC
Created attachment 214501 [details]
bsw dmesg info
Comment 14 tianye 2016-04-27 03:28:43 UTC
#Comment 12 and #Comment 13 is the boot up dmesg based on 4.6-rc2.
Comment 15 tianye 2016-04-27 03:33:17 UTC
The following info is based on  commit: c75361c0b08a during boot up, the total consuming time of intel_pstate initialization is normal as it is quite small:
[    3.412412] initcall intel_pstate_init+0x0/0x4e1 returned 0 after 1943 usecs
However there is a calltrace:


root@x-bytt02:~# dmesg | grep intel_pstate -A 10
[    3.410408] calling  intel_pstate_init+0x0/0x4e1 @ 1
[    3.410414] Intel P-state driver initializing.
[    3.411906] ------------[ cut here ]------------
[    3.411926] WARNING: CPU: 2 PID: 1 at kernel/smp.c:292 smp_call_function_sing                                                                                                                     le+0xec/0x100()
[    3.411932] Modules linked in:
[    3.411942] CPU: 2 PID: 1 Comm: swapper/0 Not tainted 4.5.0-rc3-mainline-bat-                                                                                                                     c75361c0+ #1
[    3.411946] Hardware name: ASUSTeK COMPUTER INC. T100TA/T100TA, BIOS T100TA.3                                                                                                                     04 03/14/2014
[    3.411960]  0000000000000000 ffff880075f03ce8 ffffffff813a7a2c 0000000000000                                                                                                                     000
[    3.411970]  ffffffff81acedc3 ffff880075f03d20 ffffffff81078e36 0000000000000                                                                                                                     002
[    3.411979]  ffffffff813d8d30 ffff88006f6ebe40 0000000000000002 0000000000020                                                                                                                     8b4
[    3.411982] Call Trace:
--
[    3.412077]  [<ffffffff8166eb63>] intel_pstate_set_pstate+0xd3/0x130
[    3.412087]  [<ffffffff8166f2e8>] intel_pstate_update_util+0x118/0x1c0
[    3.412097]  [<ffffffff810b1c08>] task_tick_fair+0x638/0x800
[    3.412111]  [<ffffffff810a7a42>] ? sched_clock_cpu+0x72/0xa0
[    3.412115]  [<ffffffff810a3abc>] scheduler_tick+0x5c/0xe0
[    3.412120]  [<ffffffff810e3751>] update_process_times+0x51/0x60
[    3.412124]  [<ffffffff810f016b>] tick_periodic+0x2b/0x80
[    3.412127]  [<ffffffff810f01e5>] tick_handle_periodic+0x25/0x70
[    3.412133]  [<ffffffff8104ef35>] local_apic_timer_interrupt+0x35/0x60
[    3.412139]  [<ffffffff817c7afd>] smp_apic_timer_interrupt+0x3d/0x60
[    3.412152]  [<ffffffff817c5c3c>] apic_timer_interrupt+0x8c/0xa0
[    3.412168]  <EOI>  [<ffffffff81235152>] ? fsnotify+0x12/0x430
--
[    3.412200]  [<ffffffff81dc5960>] intel_pstate_init+0x423/0x4e1
[    3.412210]  [<ffffffff81173541>] ? printk+0x4d/0x4f
[    3.412222]  [<ffffffff810021b9>] do_one_initcall+0x149/0x1e0
[    3.412233]  [<ffffffff81096400>] ? parse_args+0x290/0x480
[    3.412245]  [<ffffffff81d6a260>] kernel_init_freeable+0x16f/0x1fa
[    3.412254]  [<ffffffff81d69999>] ? initcall_blacklist+0xba/0xba
[    3.412264]  [<ffffffff817b8af0>] ? rest_init+0x80/0x80
[    3.412272]  [<ffffffff817b8afe>] kernel_init+0xe/0xf0
[    3.412282]  [<ffffffff817c524f>] ret_from_fork+0x3f/0x70
[    3.412290]  [<ffffffff817b8af0>] ? rest_init+0x80/0x80
[    3.412316] ---[ end trace ec5b269bc524fe93 ]---
[    3.412412] initcall intel_pstate_init+0x0/0x4e1 returned 0 after 1943 usecs
Comment 16 Chen Yu 2016-04-27 13:09:48 UTC
(In reply to tianye from comment #15)
> The following info is based on  commit: c75361c0b08a during boot up, the
> total consuming time of intel_pstate initialization is normal as it is quite
> small:
> [    3.412412] initcall intel_pstate_init+0x0/0x4e1 returned 0 after 1943
> usecs
> However there is a calltrace:
> 
> 
> root@x-bytt02:~# dmesg | grep intel_pstate -A 10
> [    3.410408] calling  intel_pstate_init+0x0/0x4e1 @ 1
> [    3.410414] Intel P-state driver initializing.
> [    3.411906] ------------[ cut here ]------------
> [    3.411926] WARNING: CPU: 2 PID: 1 at kernel/smp.c:292
> smp_call_function_sing                                                      
The warn should be fixed by 
commit fdfdb2b1301670a69195ba1e5666df4a7f02eb46
    intel_pstate: Do not call wrmsrl_on_cpu() with disabled interrupts

maybe we need to find a way to do a bisect inside the  merge commit, +Aaron who has bisected inside a merge commit.
Comment 17 Rafael J. Wysocki 2016-04-27 20:23:50 UTC
@tianye: Please check commit fdfdb2b13016 intel_pstate: Do not call wrmsrl_on_cpu() with disabled interrupts now.
Comment 18 Rafael J. Wysocki 2016-04-27 21:03:03 UTC
BTW, did you check if reverting commit 3ce093d4de753d6c92cc09366e29d0618a62f542 makes the problem go away on the T100?
Comment 19 tianye 2016-04-28 02:08:40 UTC
(In reply to Rafael J. Wysocki from comment #17)
> @tianye: Please check commit fdfdb2b13016 intel_pstate: Do not call
> wrmsrl_on_cpu() with disabled interrupts now.


commit: fdfdb2b1301

test results on T100:
[    3.342220] calling  intel_pstate_init+0x0/0x4e1 @ 1
[    3.344495] initcall intel_pstate_init+0x0/0x4e1 returned 0 after 2215 usecs
Test resutls on BSW:
[    3.266675] calling  intel_pstate_init+0x0/0x4e1 @ 1
[    3.268923] initcall intel_pstate_init+0x0/0x4e1 returned 0 after 2182 usecs
Comment 20 tianye 2016-04-28 02:15:08 UTC
(In reply to Rafael J. Wysocki from comment #18)
> BTW, did you check if reverting commit
> 3ce093d4de753d6c92cc09366e29d0618a62f542 makes the problem go away on the
> T100?

yes, this 3ce093d4 commit makes the problem go away on the T100.

Test resutls on T100:

[    3.341254] calling  intel_pstate_init+0x0/0x471 @ 1
[    3.343167] initcall intel_pstate_init+0x0/0x471 returned 0 after 1853 usecs
Comment 21 tianye 2016-04-28 07:04:13 UTC
Test the latest mainline kernel(b75a2bf89)on BSW and T100.

Kernel paratinitcall_debug text no_console_suspend ignore_loglevel resume=/dev/sda3

Test results on BSW: 
[    3.548955] calling  intel_pstate_init+0x0/0x4e1 @ 1
[    3.566233] initcall intel_pstate_init+0x0/0x4e1 returned 0 after 12993 usecs


Test results on T100:
[    3.494392] calling  intel_pstate_init+0x0/0x4e1 @ 1
[    3.622756] initcall intel_pstate_init+0x0/0x4e1 returned 0 after 130085 usecs
Comment 22 Rafael J. Wysocki 2016-04-28 13:51:58 UTC
(In reply to tianye from comment #20)
> (In reply to Rafael J. Wysocki from comment #18)
> > BTW, did you check if reverting commit
> > 3ce093d4de753d6c92cc09366e29d0618a62f542 makes the problem go away on the
> > T100?
> 
> yes, this 3ce093d4 commit makes the problem go away on the T100.
> 
> Test resutls on T100:
> 
> [    3.341254] calling  intel_pstate_init+0x0/0x471 @ 1
> [    3.343167] initcall intel_pstate_init+0x0/0x471 returned 0 after 1853
> usecs

That's important, so let me double check: If you revert commit 3ce093d4, the problem goes away on the T100.

Is that correct?
Comment 23 Chen Yu 2016-05-09 17:59:41 UTC
I can reproduce it on my laptop, and the reason is the following commit:
commit bb6ab52f2befe1fb29ac198f27d8a6aadf510f81 (intel_pstate: Do not set utilization update hook too early), which move the assignment of  utilization update hook from intel_pstate_init_cpu to intel_pstate_set_policy(), however after moving it to set_policy, we need to deal with  synchronization, thus synchronize_sched() is used, which is time costy because it need to wait for all the CPUs to finish the grace period.
Actuall we don't need to synchronize_sched during bootup, this is a trial patch to bypass the synchronize_sched during bootup.
Comment 24 Chen Yu 2016-05-09 18:01:08 UTC
Created attachment 215651 [details]
avoid sync during cpufreq initialization
Comment 25 Rafael J. Wysocki 2016-05-09 21:15:29 UTC
OK

Thanks for figuring this out!

Is this reproducible without ignore_loglevel?
Comment 26 Rafael J. Wysocki 2016-05-10 00:45:50 UTC
In any case, the patch from comment #24 is correct, but please rename util_running to something like update_util_set.
Comment 27 Chen Yu 2016-05-10 08:15:41 UTC
(In reply to Rafael J. Wysocki from comment #25)
> OK
> 
> Thanks for figuring this out!
> 
> Is this reproducible without ignore_loglevel?

This is interesting, I've done some experiments, and the result shows
that, on pure 4.6.0-rc7, the time consumption for intel_pstate without
ignore_loglevel is nearly 50ms, while with ignore_loglevel it is about 100ms+,
so although there is some reducing, I don't think remove ignore_loglevel would solve it.
After #Comment 24 applied, the time for intel_pstate_init dropped to 4ms.


BTW, a scenario for the reason why remove ignore_loglevel would reduce some lantency may be like this:


When a process invokes synchronize_sched in intel_pstate_set_policy, it is very likely this process will be scheduled out, then other process switch in, such as a USB driver, so if ignore_loglevel is set, the USB driver will bypass the printk level checking and leverages the console driver to write these logs out. However if ignore_loglevel is removed, only printk message level <= 6(by pass debug messages) will be passed to console drivers, otherwise the log message stays in printk's internal buffer. 
And since the console_driver-> write maybe a little time-costly, we saw the extra (100-50) ms.
What we see in dmesg is the content of printk buffer, since the sequence of logs in dmesg is not strictly the same as it is outputed in console_driver->write, because they might be running  parallelly, so we can not judge if there is other driver printing during intel_pstate_init only be dmesg logs(As Tianye once attached).
Comment 28 Chen Yu 2016-05-10 08:16:50 UTC
(In reply to Rafael J. Wysocki from comment #26)
> In any case, the patch from comment #24 is correct, but please rename
> util_running to something like update_util_set.

OK, I'll change it, thanks!
Comment 29 Rafael J. Wysocki 2016-05-10 18:57:58 UTC
So now a simple question.

Yes, it takes more time for the driver to initialize now, but why is this a problem really?

Does it increase the system's boot time significantly?  Or the suspend/resume time?
Comment 30 Chen Yu 2016-05-11 00:06:31 UTC
(In reply to Rafael J. Wysocki from comment #29)
> So now a simple question.
> 
> Yes, it takes more time for the driver to initialize now, but why is this a
> problem really?
> 
> Does it increase the system's boot time significantly?  Or the
> suspend/resume time?
It is not a real problem IMO, I guess QA is using thresholds to measure every driver's init time, but the result does not affect the system boot time or suspend/resume time significantly: the time of  increment is small, and the drivers are running parallelly.
Comment 31 Rafael J. Wysocki 2016-05-11 00:20:42 UTC
(In reply to Chen Yu from comment #30)
> (In reply to Rafael J. Wysocki from comment #29)
> > So now a simple question.
> > 
> > Yes, it takes more time for the driver to initialize now, but why is this a
> > problem really?
> > 
> > Does it increase the system's boot time significantly?  Or the
> > suspend/resume time?
> It is not a real problem IMO, I guess QA is using thresholds to measure
> every driver's init time, but the result does not affect the system boot
> time or suspend/resume time significantly: the time of  increment is small,
> and the drivers are running parallelly.

OK, so this is a change in behavior and not really a bug.

Closing as "invalid" and we'll discuss the optimization patch on the mailing list.