From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753039AbbA2O7W (ORCPT ); Thu, 29 Jan 2015 09:59:22 -0500 Received: from mail-qg0-f46.google.com ([209.85.192.46]:43036 "EHLO mail-qg0-f46.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751624AbbA2O7T (ORCPT ); Thu, 29 Jan 2015 09:59:19 -0500 From: "S. Gilles" X-Google-Original-From: "S. Gilles" Date: Thu, 29 Jan 2015 09:59:08 -0500 To: Tomi Valkeinen Cc: "S. Gilles" , Jean-Christophe Plagniol-Villard , Maik Broemme , linux-fbdev , linux-kernel , Thierry Reding Subject: Re: i915 framebuffer init too slow to find logo Message-ID: <20150129145907.GA2440@number16> References: <20150129023247.GA10967@number16> <54C9EAC3.9040509@ti.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <54C9EAC3.9040509@ti.com> User-Agent: Mutt/1.5.23 (2014-03-12) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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] [] dump_stack+0x45/0x57 [ 0.303677] [] i915_pci_probe+0x1a/0x68 [ 0.303769] [] pci_device_probe+0x54/0xa3 [ 0.303850] [] driver_probe_device+0x99/0x1c8 [ 0.303916] [] __driver_attach+0x5d/0x80 [ 0.303980] [] ? __device_attach+0x38/0x38 [ 0.305851] [] bus_for_each_dev+0x7b/0x85 [ 0.305914] [] driver_attach+0x19/0x1b [ 0.305975] [] bus_add_driver+0x109/0x1d3 [ 0.306038] [] driver_register+0x8a/0xc7 [ 0.306141] [] __pci_register_driver+0x5c/0x60 [ 0.306219] [] ? ftrace_define_fields_drm_vblank_event_delivered+0x9f/0x9f [ 0.306329] [] drm_pci_init+0x4d/0xcd [ 0.306428] [] ? ftrace_define_fields_drm_vblank_event_delivered+0x9f/0x9f [ 0.306505] [] i915_init+0x8a/0x92 [ 0.306566] [] ? ftrace_define_fields_drm_vblank_event_delivered+0x9f/0x9f [ 0.306650] [] do_one_initcall+0xe9/0x172 [ 0.306746] [] kernel_init_freeable+0x117/0x19f [ 0.306827] [] ? initcall_blacklist+0xa3/0xa3 [ 0.306926] [] ? rest_init+0xb6/0xb6 [ 0.306993] [] kernel_init+0x9/0xd0 [ 0.307085] [] ret_from_fork+0x7c/0xb0 [ 0.307176] [] ? 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] [] dump_stack+0x45/0x57 [ 0.646736] [] ? fb_console_init+0x116/0x116 [ 0.646738] [] fb_logo_late_init+0x17/0x22 [ 0.646741] [] do_one_initcall+0xe9/0x172 [ 0.646744] [] kernel_init_freeable+0x117/0x19f [ 0.646745] [] ? initcall_blacklist+0xa3/0xa3 [ 0.646747] [] ? rest_init+0xb6/0xb6 [ 0.646749] [] kernel_init+0x9/0xd0 [ 0.646752] [] ret_from_fork+0x7c/0xb0 [ 0.646754] [] ? 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] [] dump_stack+0x45/0x57 [ 1.162661] [] fb_find_logo+0xd/0x43 [ 1.162669] [] fb_prepare_logo+0x87/0x12d [ 1.162675] [] fbcon_prepare_logo+0x7f/0x2e8 [ 1.162680] [] fbcon_init+0x3d9/0x447 [ 1.162688] [] visual_init+0xb7/0x10d [ 1.162695] [] do_bind_con_driver+0x1ab/0x2cd [ 1.162702] [] do_take_over_console+0x132/0x162 [ 1.162707] [] do_fbcon_takeover+0x56/0x9a [ 1.162712] [] fbcon_event_notify+0x31c/0x644 [ 1.162718] [] notifier_call_chain+0x39/0x5c [ 1.162723] [] __blocking_notifier_call_chain+0x47/0x60 [ 1.162729] [] blocking_notifier_call_chain+0xf/0x11 [ 1.162735] [] fb_notifier_call_chain+0x16/0x18 [ 1.162741] [] register_framebuffer+0x261/0x299 [ 1.162750] [] drm_fb_helper_initial_config+0x26e/0x328 [ 1.162757] [] intel_fbdev_initial_config+0x16/0x18 [ 1.162762] [] async_run_entry_fn+0x33/0xca [ 1.162770] [] process_one_work+0x223/0x3f9 [ 1.162775] [] ? process_one_work+0x1a7/0x3f9 [ 1.162781] [] worker_thread+0x260/0x354 [ 1.162788] [] ? cancel_delayed_work_sync+0x10/0x10 [ 1.162794] [] kthread+0xe8/0xf0 [ 1.162802] [] ? kthread_create_on_node+0x1b1/0x1b1 [ 1.162810] [] ret_from_fork+0x7c/0xb0 [ 1.162817] [] ? 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