<html>
<head>
<base href="https://bugs.freedesktop.org/" />
</head>
<body>
<p>
<div>
<b><a class="bz_bug_link
bz_status_NEW "
title="NEW --- - [HSW bisected] i915 module resume time regression"
href="https://bugs.freedesktop.org/show_bug.cgi?id=65922#c8">Comment # 8</a>
on <a class="bz_bug_link
bz_status_NEW "
title="NEW --- - [HSW bisected] i915 module resume time regression"
href="https://bugs.freedesktop.org/show_bug.cgi?id=65922">bug 65922</a>
from <span class="vcard"><a class="email" href="mailto:cancan.feng@intel.com" title="cancan,feng <cancan.feng@intel.com>"> <span class="fn">cancan,feng</span></a>
</span></b>
<pre>(In reply to <a href="show_bug.cgi?id=65922#c4">comment #4</a>)
<span class="quote">> During resume:
>
> good -> [ 24.789721] call 0000:00:02.0+ returned 0 after 253503 usecs
> bad -> [ 31.337787] call 0000:00:02.0+ returned 0 after 38479 usecs
>
> So switchless is indeed doing its job in speeding up resume. So I guess we
> need to look at what happens after the kernel finishes its resume. How are
> you measuring the resume time?</span >
1. After booting a machine, I will first do a S3 suspend-resume cycle, then
dmesg | grep -i -e "i915_init\|PM:.*complete\|00:02.0+"
We will get some message as following(Here I used attachment good_commit.dmesg,
dmesg of good commit):
[ 1.381662] calling i915_init+0x0/0x68 [i915] @ 1249
[ 1.826391] initcall i915_init+0x0/0x68 [i915] returned 0 after 434521 usecs
[ 30.819536] calling 0000:00:02.0+ @ 3917, parent: pci0000:00
[ 30.860073] call 0000:00:02.0+ returned 0 after 39605 usecs
[ 30.936632] PM: suspend of devices complete after 124.805 msecs
[ 30.936957] PM: late suspend of devices complete after 0.322 msecs
[ 30.981010] calling 0000:00:02.0+ @ 3841, parent: pci0000:00
[ 30.981011] call 0000:00:02.0+ returned 0 after 0 usecs
[ 30.981071] PM: noirq suspend of devices complete after 44.137 msecs
[ 31.199416] calling 0000:00:02.0+ @ 3841, parent: pci0000:00
[ 31.210059] call 0000:00:02.0+ returned 0 after 10398 usecs
[ 31.298228] PM: noirq resume of devices complete after 98.936 msecs
[ 31.298385] PM: early resume of devices complete after 0.129 msecs
[ 31.298404] calling 0000:00:02.0+ @ 3914, parent: pci0000:00
[ 31.337787] call 0000:00:02.0+ returned 0 after 38479 usecs
[ 36.313220] PM: resume of devices complete after 5017.604 msecs
So, we will get resume time: 10398 usecs + 38479 usecs = 48877 usecs = 48.877
msecs
2. For the bad_commit.dmesg,
[ 1.871578] initcall i915_init+0x0/0x68 [i915] returned 0 after 478124 usecs
[ 24.050262] calling 0000:00:02.0+ @ 3861, parent: pci0000:00
[ 24.080930] call 0000:00:02.0+ returned 0 after 29964 usecs
[ 24.167496] PM: suspend of devices complete after 123.843 msecs
[ 24.167819] PM: late suspend of devices complete after 0.321 msecs
[ 24.211848] calling 0000:00:02.0+ @ 3753, parent: pci0000:00
[ 24.211849] call 0000:00:02.0+ returned 0 after 0 usecs
[ 24.211909] PM: noirq suspend of devices complete after 44.112 msecs
[ 24.431277] calling 0000:00:02.0+ @ 3753, parent: pci0000:00
[ 24.441924] call 0000:00:02.0+ returned 0 after 10402 usecs
[ 24.530095] PM: noirq resume of devices complete after 98.940 msecs
[ 24.530252] PM: early resume of devices complete after 0.129 msecs
[ 24.530276] calling 0000:00:02.0+ @ 25, parent: pci0000:00
[ 24.789721] call 0000:00:02.0+ returned 0 after 253503 usecs
[ 29.546061] PM: resume of devices complete after 5018.598 msecs
resume time is: 10402 usecs + 253503 usecs = 263905 usecs = 263.905 msecs</pre>
</div>
</p>
<hr>
<span>You are receiving this mail because:</span>
<ul>
<li>You are the QA Contact for the bug.</li>
<li>You are the assignee for the bug.</li>
</ul>
</body>
</html>