Re: Slow booting on x15

From: Grygorii Strashko <grygorii.strashko@ti.com>
To: Laurent Pinchart <laurent.pinchart@ideasonboard.com>,
	Tony Lindgren <tony@atomide.com>,
	Saravana Kannan <saravanak@google.com>,
	"Rafael J. Wysocki" <rjw@rjwysocki.net>,
	Ulf Hansson <ulf.hansson@linaro.org>,
	Rob Herring <robh+dt@kernel.org>
Cc: Peter Ujfalusi <peter.ujfalusi@ti.com>,
	Tomi Valkeinen <tomi.valkeinen@ti.com>,
	Linux-OMAP <linux-omap@vger.kernel.org>,
	Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
	<linux-pm@vger.kernel.org>,
	Geert Uytterhoeven <geert+renesas@glider.be>
Subject: Re: Slow booting on x15
Date: Thu, 1 Oct 2020 15:56:12 +0300	[thread overview]
Message-ID: <60ea4b42-fbc2-2b80-7eab-8a236581d4c9@ti.com> (raw)
In-Reply-To: <20201001082256.GA3722@pendragon.ideasonboard.com>



On 01/10/2020 11:22, Laurent Pinchart wrote:
> Hi Tony,
> 
> On Thu, Oct 01, 2020 at 11:17:48AM +0300, Tony Lindgren wrote:
>> * Tony Lindgren <tony@atomide.com> [201001 07:53]:
>>> * Peter Ujfalusi <peter.ujfalusi@ti.com> [200930 12:41]:
>>>> Fwiw on my beagle x15
>>>>
>>>> v5.8
>>>> [    9.908787] Run /sbin/init as init process
>>>>
>>>> v5.9-rc7
>>>> [   15.085373] Run /sbin/init as init process
>>>>
>>>>
>>>> It appears to be 'fixed' in next-20200928: the board does not even boot.
>>>
>>> Yeah so it seems :(
>>>
>>>> next-20200928 on omap5
>>>> [    9.936806] Run /sbin/init as init process
>>>>
>>>>
>>>> -rc7 spends most of it's time:
>>>> [    7.635530] Micrel KSZ9031 Gigabit PHY 48485000.mdio:01: attached PHY driver [Micrel KSZ9031 Gigabit PHY] (mii_bus:phy_addr=48485000.mdio:01, irq=POLL)
>>>> [   14.956671] cpsw 48484000.ethernet eth0: Link is Up - 1Gbps/Full - flow control off
>>>> [   15.005211] IP-Config: Complete:
>>>
>>> Booting with initcall_debug I see this with current Linux next:
>>>
>>> ...
>>> [    1.697313] cpuidle: using governor menu
>>> [    1.701353] initcall init_menu+0x0/0xc returned 0 after 0 usecs
>>> [    1.707458] calling  gpmc_init+0x0/0x10 @ 1
>>> [    1.711784] initcall gpmc_init+0x0/0x10 returned 0 after 0 usecs
>>> [    1.717974] calling  omap3_l3_init+0x0/0x10 @ 1
>>> [    1.722653] initcall omap3_l3_init+0x0/0x10 returned 0 after 0 usecs
>>> [    1.729201] calling  omap_l3_init+0x0/0x10 @ 1
>>> [    1.733791] initcall omap_l3_init+0x0/0x10 returned 0 after 0 usecs
>>> [    1.740314] calling  gate_vma_init+0x0/0x70 @ 1
>>> [    1.744976] initcall gate_vma_init+0x0/0x70 returned 0 after 0 usecs
>>> [    1.751522] calling  customize_machine+0x0/0x30 @ 1
>>> [    3.823114] initcall customize_machine+0x0/0x30 returned 0 after 2011718 usecs
>>> [    3.830566] calling  init_atags_procfs+0x0/0xec @ 1
>>> [    3.835583] No ATAGs?
>>
>> And the long time above with customize_machine() ends up being
>> pdata_quirks_init() calling of_platform_populate().
> 
> That's what the delay is for me (I think I've reported that initially).
> 
>>> Laurent & Tomi, care to check what you guys see in the slow booting case
>>> after booting with initcall_debug?
>>
>> But maybe the long delay is something else for you guys so please check.
> 

It's all devlink :( Looks like sometimes, improvements (PM) could became so complicated
that time required to execute such algorithms may completely eliminate all expected benefits.
Will not be surprised if PM consumption also increased instead of decreasing in some cases.

not sure if it's 100% correct, but below diff reduces boot time
from 7.6sec to 3.7sec :P

before:
[    0.053870] cpuidle: using governor menu
[    2.505971] No ATAGs?
...
[    7.562317] Freeing unused kernel memory: 1024K

after:
[    0.053800] cpuidle: using governor menu
[    0.136853] No ATAGs?
[    3.716218] devtmpfs: mounted
[    3.719628] Freeing unused kernel memory: 1024K
[    3.724266] Run /sbin/init as init process  \x01

----

diff --git a/drivers/of/platform.c b/drivers/of/platform.c
index 071f04da32c8..e0cc37ed46ca 100644
--- a/drivers/of/platform.c
+++ b/drivers/of/platform.c
@@ -481,6 +481,7 @@ int of_platform_populate(struct device_node *root,
         pr_debug(" starting at: %pOF\n", root);
  
         device_links_supplier_sync_state_pause();
+       fw_devlink_pause();
         for_each_child_of_node(root, child) {
                 rc = of_platform_bus_create(child, matches, lookup, parent, true);
                 if (rc) {
@@ -488,6 +489,7 @@ int of_platform_populate(struct device_node *root,
                         break;
                 }
         }
+       fw_devlink_resume();
         device_links_supplier_sync_state_resume();
  
         of_node_set_flag(root, OF_POPULATED_BUS);
@@ -538,9 +540,7 @@ static int __init of_platform_default_populate_init(void)
         }
  
         /* Populate everything else. */
-       fw_devlink_pause();
         of_platform_default_populate(NULL, NULL, NULL);
-       fw_devlink_resume();
  
         return 0;
  }


-- 
Best regards,
grygorii
