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_pstate | Assignee: | 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 |
||
[ 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 This issue still exists on mainline kernel 4.6-rc5. [ 1.978834] calling intel_pstate_init+0x0/0x404 @ 1 [ 2.080034] initcall intel_pstate_init+0x0/0x404 returned 0 after 97662 usecs (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? 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> (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. 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? 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 (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 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? Also please check this commit: c75361c0b08a cpufreq: Make cpufreq_quick_get() safe to call Created attachment 214491 [details]
t100_dmesg info
Created attachment 214501 [details]
bsw dmesg info
#Comment 12 and #Comment 13 is the boot up dmesg based on 4.6-rc2. 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 (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. @tianye: Please check commit fdfdb2b13016 intel_pstate: Do not call wrmsrl_on_cpu() with disabled interrupts now. BTW, did you check if reverting commit 3ce093d4de753d6c92cc09366e29d0618a62f542 makes the problem go away on the T100? (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 (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 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 (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? 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. Created attachment 215651 [details]
avoid sync during cpufreq initialization
OK Thanks for figuring this out! Is this reproducible without ignore_loglevel? In any case, the patch from comment #24 is correct, but please rename util_running to something like update_util_set. (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). (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! 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? (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. (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. |
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