i915 framebuffer init too slow to find logo

i915 framebuffer init too slow to find logo

[S. Gilles]

Since commit 92b004d1aa9f367c372511ca0330f58216b25703 : prevent use of
logs after they have been freed, my i915 machine has no logo on boot
(reverting that commit brings it back on recent trees). My .config
builds nothing but wireless as =m, so I think this is a genuine false
positive (as predicted by the commit). Examining an augmented dmesg,
it appears that the framebuffer setup is too slow by about 0.3s, which
I wouldn't really expect from this system/driver.

Is this slowness considered worth fixing, or is this issue considered
too cosmetic? (Or is this just PEBKAC?)

Possibly useful information:

$ lspci | grep VGA
00:02.0 VGA compatible controller: Intel Corporation 2nd Generation Core Processor Family Integrated Graphics Controller (rev 09)

>From various printk()s, it looks like the slow portion of
fb_console_init() is restore_fbdev_mode(), specifically
drm_mode_set_config_internal(), which takes about 0.45s, while the
fb_logo_late_init() call happens about 0.15s into that. I can give the
full details if requested.

Possibly relevant .config bits:

# Graphics support
CONFIG_AGP=y
CONFIG_AGP_INTEL=y
CONFIG_INTEL_GTT=y
CONFIG_VGA_ARB=y
CONFIG_VGA_ARB_MAX_GPUS=16

# Direct Rendering Manager
CONFIG_DRM=y
CONFIG_DRM_KMS_HELPER=y
CONFIG_DRM_KMS_FB_HELPER=y

# I2C encoder or helper chips
CONFIG_DRM_I915=y
CONFIG_DRM_I915_KMS=y
CONFIG_DRM_I915_FBDEV=y
CONFIG_DRM_I915_PRELIMINARY_HW_SUPPORT=y

# Frame buffer Devices
CONFIG_FB=y
CONFIG_FIRMWARE_EDID=y
CONFIG_FB_CMDLINE=y
CONFIG_FB_CFB_FILLRECT=y
CONFIG_FB_CFB_COPYAREA=y
CONFIG_FB_CFB_IMAGEBLIT=y

# Frame buffer hardware drivers
CONFIG_BACKLIGHT_LCD_SUPPORT=y
CONFIG_LCD_CLASS_DEVICE=y
CONFIG_LCD_PLATFORM=y
CONFIG_BACKLIGHT_CLASS_DEVICE=y
CONFIG_BACKLIGHT_GENERIC=y
CONFIG_HDMI=y

# Console display driver support
CONFIG_VGA_CONSOLE=y
CONFIG_DUMMY_CONSOLE=y
CONFIG_FRAMEBUFFER_CONSOLE=y
CONFIG_FRAMEBUFFER_CONSOLE_DETECT_PRIMARY=y
CONFIG_FRAMEBUFFER_CONSOLE_ROTATION=y
CONFIG_LOGO=y
CONFIG_LOGO_LINUX_MONO=y
CONFIG_LOGO_LINUX_VGA16=y
CONFIG_LOGO_LINUX_CLUT224=y

-- 
S. Gilles

Re: i915 framebuffer init too slow to find logo

[Tomi Valkeinen]

[-- Attachment #1: Type: text/plain, Size: 2202 bytes --]

On 29/01/15 04:32, S. Gilles wrote:
> Since commit 92b004d1aa9f367c372511ca0330f58216b25703 : prevent use of
> logs after they have been freed, my i915 machine has no logo on boot
> (reverting that commit brings it back on recent trees). My .config
> builds nothing but wireless as =m, so I think this is a genuine false
> positive (as predicted by the commit). Examining an augmented dmesg,

It's not so much about modules, but when the code tries to use the
logos. Drivers as modules might cause the use of logos to happen later,
but that's only one possible reason.

> it appears that the framebuffer setup is too slow by about 0.3s, which
> I wouldn't really expect from this system/driver.
> 
> Is this slowness considered worth fixing, or is this issue considered
> too cosmetic? (Or is this just PEBKAC?)
> 
> Possibly useful information:
> 
> $ lspci | grep VGA
> 00:02.0 VGA compatible controller: Intel Corporation 2nd Generation Core Processor Family Integrated Graphics Controller (rev 09)
> 
> From various printk()s, it looks like the slow portion of
> fb_console_init() is restore_fbdev_mode(), specifically
> drm_mode_set_config_internal(), which takes about 0.45s, while the
> fb_logo_late_init() call happens about 0.15s into that. I can give the
> full details if requested.

When does the driver probe() happen? Does the initialization happen
outside of the probe(), via workqueue or such? If so, then the fix is
valid for your case also, as the work could be ran after the logos have
been freed.

However, it does seem that the fix seems to cause logos to disappear for
many people. I'd be interesting to know how many of those cases were
working by luck, either by

1) an async work being ran fast enough, before the logos had been freed
2) the use of logos happening after the logos had been freed, but if no
one had trashed the logo memory yet, it still works

I don't care so much about the logo myself but people do seem to like
it, so perhaps we need to change the code as Thierry suggested:
allocating memory for the logos and keeping them in memory until someone
uses them the first time, and then free the memory.

 Tomi



[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 819 bytes --]

Re: i915 framebuffer init too slow to find logo

[S. Gilles]

On 2015-01-29T10:09:39+0200, Tomi Valkeinen wrote:
> On 29/01/15 04:32, S. Gilles wrote:
> > Since commit 92b004d1aa9f367c372511ca0330f58216b25703 : prevent use of
> > logs after they have been freed, my i915 machine has no logo on boot
> > (reverting that commit brings it back on recent trees). My .config
> > builds nothing but wireless as =m, so I think this is a genuine false
> > positive (as predicted by the commit). Examining an augmented dmesg,
> 
> It's not so much about modules, but when the code tries to use the
> logos. Drivers as modules might cause the use of logos to happen later,
> but that's only one possible reason.
> 
> > it appears that the framebuffer setup is too slow by about 0.3s, which
> > I wouldn't really expect from this system/driver.
> > 
> > Is this slowness considered worth fixing, or is this issue considered
> > too cosmetic? (Or is this just PEBKAC?)
> > 
> > Possibly useful information:
> > 
> > $ lspci | grep VGA
> > 00:02.0 VGA compatible controller: Intel Corporation 2nd Generation Core Processor Family Integrated Graphics Controller (rev 09)
> > 
> > From various printk()s, it looks like the slow portion of
> > fb_console_init() is restore_fbdev_mode(), specifically
> > drm_mode_set_config_internal(), which takes about 0.45s, while the
> > fb_logo_late_init() call happens about 0.15s into that. I can give the
> > full details if requested.
> 
> When does the driver probe() happen? Does the initialization happen
> outside of the probe(), via workqueue or such? If so, then the fix is
> valid for your case also, as the work could be ran after the logos have
> been freed.

It looks like the fix is indeed valid, since the initialization
happens without probe() in the trace: the result of putting
dump_stack() at the beginning of the relevant functions is (in far too
much detail)

...
[    0.302391] CPU: 1 PID: 1 Comm: swapper/0 Not tainted 3.19.0-rc5+ #26
[    0.302476] Hardware name: LENOVO 4286CTO/4286CTO, BIOS 8DET42WW (1.12 ) 04/01/2011
[    0.302561]  ffff880138ffd000 ffff880139563c98 ffffffff817945db 0000000000000126
[    0.302882]  ffffffff81849d20 ffff880139563cc8 ffffffff813b7ec4 ffff880138ffd000
[    0.303189]  ffffffff81848b10 ffffffff81c3ad58 ffff880138ffd090 ffff880139563cf8
[    0.303511] Call Trace:
[    0.303578]  [<ffffffff817945db>] dump_stack+0x45/0x57
[    0.303677]  [<ffffffff813b7ec4>] i915_pci_probe+0x1a/0x68
[    0.303769]  [<ffffffff8131c209>] pci_device_probe+0x54/0xa3
[    0.303850]  [<ffffffff8144367d>] driver_probe_device+0x99/0x1c8
[    0.303916]  [<ffffffff81443841>] __driver_attach+0x5d/0x80
[    0.303980]  [<ffffffff814437e4>] ? __device_attach+0x38/0x38
[    0.305851]  [<ffffffff81441d7c>] bus_for_each_dev+0x7b/0x85
[    0.305914]  [<ffffffff81443240>] driver_attach+0x19/0x1b
[    0.305975]  [<ffffffff81442f28>] bus_add_driver+0x109/0x1d3
[    0.306038]  [<ffffffff81443c20>] driver_register+0x8a/0xc7
[    0.306141]  [<ffffffff8131bf4b>] __pci_register_driver+0x5c/0x60
[    0.306219]  [<ffffffff81d052cc>] ? ftrace_define_fields_drm_vblank_event_delivered+0x9f/0x9f
[    0.306329]  [<ffffffff813a5fa3>] drm_pci_init+0x4d/0xcd
[    0.306428]  [<ffffffff81d052cc>] ? ftrace_define_fields_drm_vblank_event_delivered+0x9f/0x9f
[    0.306505]  [<ffffffff81d05356>] i915_init+0x8a/0x92
[    0.306566]  [<ffffffff81d052cc>] ? ftrace_define_fields_drm_vblank_event_delivered+0x9f/0x9f
[    0.306650]  [<ffffffff8100030d>] do_one_initcall+0xe9/0x172
[    0.306746]  [<ffffffff81ccefb1>] kernel_init_freeable+0x117/0x19f
[    0.306827]  [<ffffffff81cce7c0>] ? initcall_blacklist+0xa3/0xa3
[    0.306926]  [<ffffffff8178e559>] ? rest_init+0xb6/0xb6
[    0.306993]  [<ffffffff8178e562>] kernel_init+0x9/0xd0
[    0.307085]  [<ffffffff8179ceec>] ret_from_fork+0x7c/0xb0
[    0.307176]  [<ffffffff8178e559>] ? rest_init+0xb6/0xb6
...
[    0.646722] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 3.19.0-rc5+ #26
[    0.646723] Hardware name: LENOVO 4286CTO/4286CTO, BIOS 8DET42WW (1.12 ) 04/01/2011
[    0.646726]  ffff8800b5aff000 ffff880139563e78 ffffffff817945db 0000000000000013
[    0.646728]  ffffffff81d00a08 ffff880139563e88 ffffffff81d00a1f ffff880139563ef8
[    0.646730]  ffffffff8100030d 0000000000000000 ffffffff81b7f6b8 0000019d00070007
[    0.646730] Call Trace:
[    0.646733]  [<ffffffff817945db>] dump_stack+0x45/0x57
[    0.646736]  [<ffffffff81d00a08>] ? fb_console_init+0x116/0x116
[    0.646738]  [<ffffffff81d00a1f>] fb_logo_late_init+0x17/0x22
[    0.646741]  [<ffffffff8100030d>] do_one_initcall+0xe9/0x172
[    0.646744]  [<ffffffff81ccefb1>] kernel_init_freeable+0x117/0x19f
[    0.646745]  [<ffffffff81cce7c0>] ? initcall_blacklist+0xa3/0xa3
[    0.646747]  [<ffffffff8178e559>] ? rest_init+0xb6/0xb6
[    0.646749]  [<ffffffff8178e562>] kernel_init+0x9/0xd0
[    0.646752]  [<ffffffff8179ceec>] ret_from_fork+0x7c/0xb0
[    0.646754]  [<ffffffff8178e559>] ? rest_init+0xb6/0xb6
...
[    1.162602] CPU: 1 PID: 6 Comm: kworker/u16:0 Not tainted 3.19.0-rc5+ #26
[    1.162605] Hardware name: LENOVO 4286CTO/4286CTO, BIOS 8DET42WW (1.12 ) 04/01/2011
[    1.162627]  0000000000000018 ffff8801395a3918 ffffffff817945db ffffffff81caeee0
[    1.162634]  0000000000000018 ffff8801395a3938 ffffffff8178f5f7 0000000000000000
[    1.162641]  ffff8800b5ff0c00 ffff8801395a3968 ffffffff813321fb 0000000000000320
[    1.162643] Call Trace:
[    1.162653]  [<ffffffff817945db>] dump_stack+0x45/0x57
[    1.162661]  [<ffffffff8178f5f7>] fb_find_logo+0xd/0x43
[    1.162669]  [<ffffffff813321fb>] fb_prepare_logo+0x87/0x12d
[    1.162675]  [<ffffffff81328fed>] fbcon_prepare_logo+0x7f/0x2e8
[    1.162680]  [<ffffffff8132b3b9>] fbcon_init+0x3d9/0x447
[    1.162688]  [<ffffffff813817de>] visual_init+0xb7/0x10d
[    1.162695]  [<ffffffff81383000>] do_bind_con_driver+0x1ab/0x2cd
[    1.162702]  [<ffffffff813835e1>] do_take_over_console+0x132/0x162
[    1.162707]  [<ffffffff813292ac>] do_fbcon_takeover+0x56/0x9a
[    1.162712]  [<ffffffff8132cb6a>] fbcon_event_notify+0x31c/0x644
[    1.162718]  [<ffffffff810bcf4f>] notifier_call_chain+0x39/0x5c
[    1.162723]  [<ffffffff810bd208>] __blocking_notifier_call_chain+0x47/0x60
[    1.162729]  [<ffffffff810bd230>] blocking_notifier_call_chain+0xf/0x11
[    1.162735]  [<ffffffff81331cc3>] fb_notifier_call_chain+0x16/0x18
[    1.162741]  [<ffffffff81333b50>] register_framebuffer+0x261/0x299
[    1.162750]  [<ffffffff8139bcfb>] drm_fb_helper_initial_config+0x26e/0x328
[    1.162757]  [<ffffffff8141da68>] intel_fbdev_initial_config+0x16/0x18
[    1.162762]  [<ffffffff810be0a0>] async_run_entry_fn+0x33/0xca
[    1.162770]  [<ffffffff810b800b>] process_one_work+0x223/0x3f9
[    1.162775]  [<ffffffff810b7f8f>] ? process_one_work+0x1a7/0x3f9
[    1.162781]  [<ffffffff810b8905>] worker_thread+0x260/0x354
[    1.162788]  [<ffffffff810b86a5>] ? cancel_delayed_work_sync+0x10/0x10
[    1.162794]  [<ffffffff810bc333>] kthread+0xe8/0xf0
[    1.162802]  [<ffffffff810bc24b>] ? kthread_create_on_node+0x1b1/0x1b1
[    1.162810]  [<ffffffff8179ceec>] ret_from_fork+0x7c/0xb0
[    1.162817]  [<ffffffff810bc24b>] ? kthread_create_on_node+0x1b1/0x1b1
...

> However, it does seem that the fix seems to cause logos to disappear for
> many people. I'd be interesting to know how many of those cases were
> working by luck, either by
> 
> 1) an async work being ran fast enough, before the logos had been freed
> 2) the use of logos happening after the logos had been freed, but if no
> one had trashed the logo memory yet, it still works

In my case, it looks like #1 is the case: free_initmem() was called
~6.96s into boot on the run matching the traces above, so the initdata
looks safe barring async trickery.

> I don't care so much about the logo myself but people do seem to like
> it, so perhaps we need to change the code as Thierry suggested:
> allocating memory for the logos and keeping them in memory until someone
> uses them the first time, and then free the memory.

I'm not too concerned about the pixels myself, but I was concerned
that the initialization was happening slow enough to be caught by this
(perhaps this might have been a warning sign if setting up the console
was depending unsafely on other initdata?). It is also rather obvious,
so it's something a novice like myself can easily bisect and report.

-- 
S. Gilles