Bug 72211 - [HSW eDP] Response time larger than expected
Summary: [HSW eDP] Response time larger than expected
Status: CLOSED FIXED
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: unspecified
Hardware: Other Linux (All)
: high normal
Assignee: Jesse Barnes
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard:
Keywords:
Depends on: 72352
Blocks:
  Show dependency treegraph
 
Reported: 2013-12-02 03:11 UTC by Qingshuai Tian
Modified: 2017-10-06 14:41 UTC (History)
6 users (show)

See Also:
i915 platform:
i915 features:


Attachments
dmseg after a round of s3 (121.67 KB, text/plain)
2013-12-02 03:11 UTC, Qingshuai Tian
no flags Details
dmesg of S3 resonse time with eDP (121.77 KB, text/plain)
2013-12-05 09:33 UTC, Qingshuai Tian
no flags Details
dmesg after a round of s3 with the suspend improve kernel (121.67 KB, text/plain)
2013-12-17 03:41 UTC, Qingshuai Tian
no flags Details
dmesg of S3 resonse time with HDMI on HSw (123.40 KB, text/plain)
2013-12-19 02:09 UTC, Qingshuai Tian
no flags Details
dmesg with i915.fastboot=1 set (121.26 KB, text/plain)
2014-01-28 08:12 UTC, Guo Jinxian
no flags Details
dmseg of latest nightly kernel(64fcdb) without i915.fastboot=1 (121.44 KB, text/plain)
2014-02-14 08:44 UTC, Qingshuai Tian
no flags Details
dmesg info with drm.debug=0x6 and i915.fastboot=1 set after a round of s3 (121.30 KB, text/plain)
2014-02-28 08:58 UTC, Qingshuai Tian
no flags Details
dmesg info of patched kernel with i915.fastboot=1 set (120.87 KB, text/plain)
2014-03-03 09:08 UTC, Qingshuai Tian
no flags Details
dmesg info with kernel from Jesse's tree on the async branch (121.40 KB, text/plain)
2014-03-06 05:30 UTC, Qingshuai Tian
no flags Details

Description Qingshuai Tian 2013-12-02 03:11:28 UTC
Created attachment 90071 [details]
dmseg after a round of s3

Environment:
--------------------
Kernel: (drm-intel-nightly)be46ffd48ba34189336c6fe420ff3370dcd36c60
Some additional commit info:
Author: Ville Syrjälä <ville.syrjala@linux.intel.com>
Date:   Fri Nov 29 13:21:49 2013 +0200

    drm/i915: Fix port name in vlv_wait_port_ready() timeout warning

Bug detailed description:
-----------------------------
When I test on a HSW ULT machine with a eDP monitor , 3 response time of i915 init,suspend and resume are quite larger than expected. 
I list the result below:
       Acquire initcall time: 1672.811 msecs 
       Acquire suspend time: 1093.865 msecs  
       Acquire resume time: 625.535 msecs 

Machin Info: Lenovo idealpad u330p
BIOS Version: 7CCN15WW
CPU: Intel(R) Core(TM) i3-4010U CPU @1.70GHZ

Reproduce Steps:
--------------------
1. Rebuild kernel with option CONFIG_PM_TRACE.
2. Boot system with kernel command: initcall_debug drm.debug=0xe
3. perform a suspend-resume cycle by executing 'echo mem > /sys/power/state'
4. The dump the dmesg with the following command:
   dmesg | grep -i -e "i915_init\|PM:.*complete\|00:02.0+"
Comment 1 Paulo Zanoni 2013-12-02 15:44:59 UTC
Hi

Is this a recent regression? If yes, can you please bisect the commit which made us below the threshold? If no, why?

Thanks,
Paulo
Comment 2 Gordon Jin 2013-12-03 00:25:43 UTC
I don't think it regression. We filed similar bug before, with eDP panel on CRB, and it's said to be related to the specific panel. 
Now we bought HSW product with integrated eDP, and want to track it here now.

The key point is eDP. The situation on DP/HDMI/VGA is much better.

And this is not HSW specific. IVB eDP is also bad.
Comment 3 Paulo Zanoni 2013-12-04 21:22:53 UTC
Hi

Can you please try this tree: http://cgit.freedesktop.org/~pzanoni/linux/?h=vdd-rework ?

Please make sure you re on the vdd-rework branch. This branch should save many milliseconds when enabling/disabling eDP. If would be nice to see how faster/slower we get with this branch.

Thanks,
Paulo
Comment 4 Qingshuai Tian 2013-12-05 09:33:39 UTC
Created attachment 90296 [details]
dmesg of S3 resonse time with eDP

I did a round of s3 with the kernel build from the tree you mentioned.

The result is as follows:
       Acquire initcall time:  1637.832 msecs 
       Acquire suspend time:  1005.944 msecs  
       Acquire resume time:  386.658 msecs 

The resume time do have reduced a lot! :)
You can check the dmesg in the attachment.
Comment 5 Paulo Zanoni 2013-12-05 12:42:32 UTC
(In reply to comment #4)
> Created attachment 90296 [details]
> dmesg of S3 resonse time with eDP
> 
> I did a round of s3 with the kernel build from the tree you mentioned.
> 
> The result is as follows:
>        Acquire initcall time:  1637.832 msecs 
>        Acquire suspend time:  1005.944 msecs  
>        Acquire resume time:  386.658 msecs 
> 
> The resume time do have reduced a lot! :)
> You can check the dmesg in the attachment.

Is this enough? What are the expected values?

Thanks,
Paulo
Comment 6 Gordon Jin 2013-12-06 01:24:16 UTC
(In reply to comment #5)
> Is this enough? What are the expected values?

Not enough. The expected value is 50ms. Or a more realistic goal is on par with DP, i.e. 265/41/215 on HSW for now.
Comment 7 Paulo Zanoni 2013-12-16 17:27:21 UTC
Hi

Could you please test this tree: http://cgit.freedesktop.org/~pzanoni/linux/?h=suspend-improvements and measure the improvements on the init/suspend/resume timings? Please make sure you're on the "suspend-improvements" branch.

I expect a huge help on eDP suspend time, but we should also see improvements on other outputs, and also on the init path.

Thanks,
Paulo
Comment 8 Qingshuai Tian 2013-12-17 03:41:09 UTC
Created attachment 90856 [details]
dmesg after a round of s3 with the suspend improve kernel

I built a kernel from the tree you gave and finished a round of s3.

The result this time is as follows:
       Acquire initcall time:  1392.780 msecs 
       Acquire suspend time:  283.063 msecs  
       Acquire resume time:  336.575 msecs
Comment 9 Qingshuai Tian 2013-12-17 05:08:22 UTC
(In reply to comment #8)
> The result this time is as follows:
>        Acquire initcall time:  1392.780 msecs 
>        Acquire suspend time:  283.063 msecs  
>        Acquire resume time:  336.575 msecs

By the way, the response time was got from HSW product with integrated eDP as above.
 
Do you need the compared data as HDMI from another HSW CRB?
Comment 10 Paulo Zanoni 2013-12-17 13:23:06 UTC
(In reply to comment #9)
> (In reply to comment #8)
> > The result this time is as follows:
> >        Acquire initcall time:  1392.780 msecs 
> >        Acquire suspend time:  283.063 msecs  
> >        Acquire resume time:  336.575 msecs
> 

So I guess that, compared with comment #1, we got about ~250ms init improvement, about 800ms suspend improvement and about 300ms resume improvement. That looks good, but we still have a long way to do for the theoretical 50ms :)

> By the way, the response time was got from HSW product with integrated eDP
> as above.
>  
> Do you need the compared data as HDMI from another HSW CRB?

I also expect some improvements on the HDMI and/or DP code, so if you'd like to test one of these, it would be nice to compare.

Thanks,
Paulo
Comment 11 Qingshuai Tian 2013-12-19 02:09:47 UTC
Created attachment 90963 [details]
dmesg of S3 resonse time with HDMI on HSw

I tested the HDMI and the result is as follows. You can check the dmesg in attachment.
        Initcall time:  214.721 msecs 
        Suspend time:  30.694 msecs  
        Resume time:  134.705 msecs 

For your information, last time the response time I got with drm-intel-nightly kernel(2013/12/04) on HDMI is as shown below:
        Initcall time:  303.983 msecs 
        Suspend time:  37.697 msecs  
        Resume time:  295.006 msecs

There is a little situation with the DP equipped HSW machine. I'll get the DP result later and inform you when it's OK. :)
Comment 12 Jesse Barnes 2014-01-28 01:08:20 UTC
Can you capture new init time numbers with i915.fastboot=1 set on the kernel command line?  You'll also want to see if you can configure grub to set a native mode if possible.  Please report any bugs you find with i915.fastboot=1 when you try it out.
Comment 13 Guo Jinxian 2014-01-28 08:09:58 UTC
(In reply to comment #12)
> Can you capture new init time numbers with i915.fastboot=1 set on the kernel
> command line?  You'll also want to see if you can configure grub to set a
> native mode if possible.  Please report any bugs you find with
> i915.fastboot=1 when you try it out.

I captured new init time numbers with i915.fastboot=1 on latest -nightly(9438dec1c7538fdd3b356a59ca929632fcb57132) kernel below:
        Initcall time:  1202.624 msecs 
        Suspend time:  21.980 msecs  
        Resume time:  65.454 msecs
Comment 14 Guo Jinxian 2014-01-28 08:12:00 UTC
Created attachment 92908 [details]
dmesg with i915.fastboot=1 set
Comment 15 Guo Jinxian 2014-02-14 07:56:08 UTC
(In reply to comment #13)
> (In reply to comment #12)
> > Can you capture new init time numbers with i915.fastboot=1 set on the kernel
> > command line?  You'll also want to see if you can configure grub to set a
> > native mode if possible.  Please report any bugs you find with
> > i915.fastboot=1 when you try it out.
> 
> I captured new init time numbers with i915.fastboot=1 on latest
> -nightly(9438dec1c7538fdd3b356a59ca929632fcb57132) kernel below:
>         Initcall time:  1202.624 msecs 
>         Suspend time:  21.980 msecs  
>         Resume time:  65.454 msecs

Sorry, the time statistics was wrong, the right result should be:
         Initcall time:  1202.624 msecs 
         Suspend time:  287.398 msecs  
         Resume time:  419.526 msecs
Please refer to attachment 92908 [details] for the dmesg.
Comment 16 Qingshuai Tian 2014-02-14 08:44:43 UTC
Created attachment 94050 [details]
dmseg of latest nightly kernel(64fcdb) without i915.fastboot=1

I captured the response time with the latest drm-intel-nightly kernel(64fcdb) on eDP monitor.

The responsetime without i915.fastboot=1:
         Initcall time:  1123 msecs 
         Suspend time:  293 msecs  
         Resume time:  314 msecs

The reponsetime with i915.fastboot=1 set :
         Initcall time:  1144 msecs 
         Suspend time:  296 msecs  
         Resume time:  313 msecs

Hope it's helpful.
Comment 17 Jesse Barnes 2014-02-27 00:54:26 UTC
Can I get the dmesg from drm.debug=6 for the fastboot case?  Looks like we failed to actually fastboot here...
Comment 18 Qingshuai Tian 2014-02-28 08:58:27 UTC
Created attachment 94865 [details]
dmesg info with drm.debug=0x6 and i915.fastboot=1 set after a round of s3

The dmesg  from drm.debug=6 for the fastboot case has been attached. 
Kernel is the latest drm-intel-nightly(513e58).

The reponsetime this time:
         Initcall time:   1107 msecs 
         Suspend time:  283 msecs  
         Resume time:  311 msecs
Comment 19 Chris Wilson 2014-02-28 10:26:55 UTC
Off-by-one in the retreived dotclock:

[    3.009792] [drm:intel_set_config_compute_mode_changes], modes are different, full mode set
[    3.009795] [drm:drm_mode_debug_printmodeline], Modeline 0:"" 0 75599 1366 1404 1426 1592 768 771 777 790 0x0 0x5
[    3.009798] [drm:drm_mode_debug_printmodeline], Modeline 19:"1366x768" 60 75600 1366 1404 1426 1592 768 771 777 790 0x48 0xa

Or maybe that is worth fuzzing?
Comment 20 Chris Wilson 2014-02-28 10:28:46 UTC
And the sync polarity is different.
Comment 21 Chris Wilson 2014-02-28 10:32:57 UTC
Out of interest, what happens with this gratuitous hack?

diff --git a/drivers/gpu/drm/i915/intel_display.c b/drivers/gpu/drm/i915/intel_display.c
index c3a955b5f14b..a8296de01eca 100644
--- a/drivers/gpu/drm/i915/intel_display.c
+++ b/drivers/gpu/drm/i915/intel_display.c
@@ -10024,6 +10024,16 @@ is_crtc_connector_off(struct drm_mode_set *set)
        return false;
 }
 
+static bool
+intel_mode_equal(const struct drm_display_mode *a,
+                const struct drm_display_mode *b)
+{
+       if (i915.fastboot)
+               return a->htotal == b->htotal && a->vtotal == b->vtotal;
+       else
+               return drm_mode_equal(a, b);
+}
+
 static void
 intel_set_config_compute_mode_changes(struct drm_mode_set *set,
                                      struct intel_set_config *config)
@@ -10059,7 +10069,7 @@ intel_set_config_compute_mode_changes(struct drm_mode_set *set,
        if (set->fb && (set->x != set->crtc->x || set->y != set->crtc->y))
                config->fb_changed = true;
 
-       if (set->mode && !drm_mode_equal(set->mode, &set->crtc->mode)) {
+       if (set->mode && !intel_mode_equal(set->mode, &set->crtc->mode)) {
                DRM_DEBUG_KMS("modes are different, full mode set\n");
                drm_mode_debug_printmodeline(&set->crtc->mode);
                drm_mode_debug_printmodeline(set->mode);
Comment 22 Qingshuai Tian 2014-03-03 09:08:06 UTC
Created attachment 95008 [details]
dmesg info of patched kernel with i915.fastboot=1 set

After applied patch in comment 21 to the latest nightly kernel(0dfe3ce67bbd11c5b5e53250b0552ac2f36ac668), the responsiveness I get with and without i915.fastboot=1 is as follows:

The reponsetime without i915.fastboot=1:
         Initcall time:   1199 msecs 
         Suspend time:  294 msecs  
         Resume time:  310 msecs

The reponsetime with i915.fastboot=1 set:
         Initcall time:   149 msecs 
         Suspend time:  264 msecs  
         Resume time:  310 msecs

But when I applied the patch and enable the fastboot, the eDP monitor was black   without any outputs after machine boot up, while the backlight was turned on.
And after the system resume from s3, the eDP monitor returned to normal by itself.
Comment 23 Jesse Barnes 2014-03-06 00:36:49 UTC
Can you try the 'async' branch of my linux repo on freedesktop.org?  It should improve the init time; I'm still working on the resume time.
Comment 24 Jesse Barnes 2014-03-06 00:43:13 UTC
git://people.freedesktop.org/~jbarnes/linux on the async branch
Comment 25 Qingshuai Tian 2014-03-06 05:30:24 UTC
Created attachment 95206 [details]
dmesg info with kernel from Jesse's tree on the async branch

I tested with the kernel built from the async branch. You can check the dmesg info in the attachment.
The results of HSW eDP responsiveness is as follows:
         Initcall time:   324 msecs 
         Suspend time:  290 msecs  
         Resume time:  548 msecs

Then I set i915.fastboot=1 on the kernel command line and retested.
The result is:
         Initcall time:   324 msecs 
         Suspend time:  283 msecs  
         Resume time:  549 msecs
Comment 26 Daniel Vetter 2014-05-16 22:07:37 UTC
Ok, time to retest upstream without any additional patches. Should be a notch faster now.
Comment 27 liulei 2014-06-09 09:19:16 UTC
(In reply to comment #26)
> Ok, time to retest upstream without any additional patches. Should be a
> notch faster now.
kernel version:
       3.15.0-rc8_drm-intel-nightly_969b3c_20140609
The result is as follows:
       Acquire initcall time:  1116.664 msecs 
       Acquire suspend time:  262.128 msecs  
       Acquire resume time:  355.50 msecs
Comment 28 liulei 2014-06-14 11:58:03 UTC
Testing based on jesse’ async branch
BDW’s data:
initcall time:  80.277  msecs 
suspend time:  257.556 msecs  
resume time:  24.531 msecs

HSW’s data:
Initcall time : 80.819 msecs
suspend time: 258.440 msecs
resume time: 73.116 msecs
Comment 29 Jesse Barnes 2014-06-24 20:35:47 UTC
Looks like the initial problem here is solved at least.  We still have a ways to go to get to the full async speeds, but that should come with Rob's atomic stuff.
Comment 30 Gordon Jin 2014-06-25 07:47:11 UTC
(In reply to comment #29)
> Looks like the initial problem here is solved at least.  We still have a
> ways to go to get to the full async speeds, but that should come with Rob's
> atomic stuff.

Jesse, did you close this bug based on the data on -nightly (comment#27) or async branch (comment#28)?
Comment 31 Jesse Barnes 2014-06-27 15:35:55 UTC
Based on comment #27 since we really improved all the times by nearly 600ms each.
Comment 32 Gordon Jin 2014-07-02 06:31:13 UTC
It's improved, but still lower than expectation, especially the init time. 
I'd suggest keeping this open until we get the init time data like comment#28 in upstream.
Comment 33 liulei 2014-09-05 02:04:39 UTC
Latest HSW responsiveness time 
Init time    62.05
Resume time  323.95
Suspend time 274.81
Comment 34 Jani Nikula 2014-09-05 07:29:20 UTC
(In reply to comment #32)
> It's improved, but still lower than expectation, especially the init time. 
> I'd suggest keeping this open until we get the init time data like
> comment#28 in upstream.

(In reply to comment #33)
> Latest HSW responsiveness time 
> Init time    62.05
> Resume time  323.95
> Suspend time 274.81

Good enough?
Comment 35 liulei 2014-09-10 02:48:30 UTC
There’re still some remaining issues. I will report anther bug (in Jira)to track.We can close this bug.
Comment 36 Elizabeth 2017-10-06 14:41:42 UTC
Closing old verified.


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.