lkml.org 
[lkml]   [2015]   [Jan]   [29]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
From
Date
SubjectRe: i915 framebuffer init too slow to find logo
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


\
 
 \ /
  Last update: 2015-01-29 16:21    [W:0.072 / U:0.016 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site