Re: [PATCH] i2c: rcar: initialize earlier using subsys_initcall()

[Wolfram Sang]

Eugeniu,

> So, the idea is that the startup improvement of rcar_i2c_driver_init()
> comes at the cost of a slower cs2000_driver_init(). In the end,
> there is no benefit

Thank you for the measurements and heads up on this! Much appreciated.
The results match my expectations.

> If evidence in the form of measurements showing improved behavior
> is not enough for the patch to be accepted, then we have no choice but
> to keep the patch out-of-tree as a "workaround", hoping that we'll be able
> to come up with a better/cleaner solution in future.

I am all with you. It is not that I don't want faster boot times. Yet,
unless we know if this is a proper solution and not a workaround for
just some use cases, I am reluctant to apply it to the upstream kernel.

Thanks and kind regards,

   Wolfram



signature.asc
Description: PGP signature

Re: [PATCH] i2c: rcar: initialize earlier using subsys_initcall()

[Eugeniu Rosca]

[re-sending due to lost To: field]

Hello Wolfram, Vladimir,

Thanks for your precious inputs.

I think you outlined two topics in your comments (based on the
description submitted with the patch). One (primary?) is related to
async probing and one (secondary, but still interesting) is related to
the minor (~7ms -> ~1ms) startup improvement of the rcar-i2c driver.

I did a little bit of research to understand what's behind the startup
improvement (hoping it is simpler to explain) and I think I reached some
conclusions. I used vanilla v4.16 kernel/defconfig/dtb and the
h3-es20-salvator-X target. The only configuration change was to enable
CONFIG_DEBUG_DRIVER and to increase CONFIG_LOG_BUF_SHIFT from 17 to 22
to avoid overwriting the printk buffer. Kernel was boot-ed "quiet"-ly.

With this HW/SW setup, I am able to confirm (based on 5 dmesg logs with
and w/o the submitted patch) that:

[1] W/o the submitted patch, rcar_i2c_driver_init takes around 7092 us
[2] With the submitted patch, rcar_i2c_driver_init takes around 1241 us

Comparing the  marked below in the two cases:
   calling  rcar_i2c_driver_init
   
   initcall rcar_i2c_driver_init+0x0/0x20 returned 0 after X us

I notice that w/o the proposed patch,  is consistently more
rich, containing output related to additional three drivers:
* cs2000-cp
* rcar-dmac
* ohci-platform

These additional lines cumulatively consume around 5-6 ms, which
is exactly the difference between [1] and [2] seen above.

To explain why these lines are present in [1], but not in [2], I checked
the order of initialization of the mentioned drivers. Here is what I see:

[11] W/o the submitted patch (in the order of execution):
InitcallTime (us)
cs2000_driver_init 30
rcar_dmac_driver_init8107
ohci_platform_init 178199
rcar_i2c_driver_init 7092
 SUM   193428

[22] With the submitted patch (in the order of execution):
InitcallTime (us)
rcar_i2c_driver_init 1241
cs2000_driver_init   5667
rcar_dmac_driver_init8160
ohci_platform_init 178110
SUM193178

So, the idea is that the startup improvement of rcar_i2c_driver_init()
comes at the cost of a slower cs2000_driver_init(). In the end,
there is no benefit and this doesn't work as an argument why the patch
should go upstream.

With regard to the primary argument, that the proposed patch
reduces/minimizes the boot time variance when switching certain drivers
like rcar-du from synchronous to asynchronous probing, I can clearly
sense this in my measurements, but I'm afraid I won't be able to provide
a simple and comprehensive explanation why this happens, since we
enter the territory of concurrent/parallel driver initialization.

If evidence in the form of measurements showing improved behavior
is not enough for the patch to be accepted, then we have no choice but
to keep the patch out-of-tree as a "workaround", hoping that we'll be able
to come up with a better/cleaner solution in future.

If you ever stumble upon a mailing list discussing how to "stabilize"
the boot time as a consequence of using asynchronous probing, then
please drop a link and this will be appreciated.

Many thanks,
Eugeniu.

Re: [PATCH] i2c: rcar: initialize earlier using subsys_initcall()

[Eugeniu Rosca]

Hello Wolfram, Vladimir,

Thanks for your precious inputs.

I think you outlined two topics in your comments (based on the
description submitted with the patch). One (primary?) is related to
async probing and one (secondary, but still interesting) is related to
the minor (~7ms -> ~1ms) startup improvement of the rcar-i2c driver.

I did a little bit of research to understand what's behind the startup
improvement (hoping it is simpler to explain) and I think I reached some
conclusions. I used vanilla v4.16 kernel/defconfig/dtb and the
h3-es20-salvator-X target. The only configuration change was to enable
CONFIG_DEBUG_DRIVER and to increase CONFIG_LOG_BUF_SHIFT from 17 to 22
to avoid overwriting the printk buffer. Kernel was boot-ed "quiet"-ly.

With this HW/SW setup, I am able to confirm (based on 5 dmesg logs with
and w/o the submitted patch) that:

[1] W/o the submitted patch, rcar_i2c_driver_init takes around 7092 us
[2] With the submitted patch, rcar_i2c_driver_init takes around 1241 us

Comparing the  marked below in the two cases:
   calling  rcar_i2c_driver_init
   
   initcall rcar_i2c_driver_init+0x0/0x20 returned 0 after X us

I notice that w/o the proposed patch,  is consistently more
rich, containing output related to additional three drivers:
* cs2000-cp
* rcar-dmac
* ohci-platform

These additional lines cumulatively consume around 5-6 ms, which
is exactly the difference between [1] and [2] seen above.

To explain why these lines are present in [1], but not in [2], I checked
the order of initialization of the mentioned drivers. Here is what I see:

[11] W/o the submitted patch (in the order of execution):
InitcallTime (us)
cs2000_driver_init 30
rcar_dmac_driver_init8107
ohci_platform_init 178199
rcar_i2c_driver_init 7092
 SUM   193428

[22] With the submitted patch (in the order of execution):
InitcallTime (us)
rcar_i2c_driver_init 1241
cs2000_driver_init   5667
rcar_dmac_driver_init8160
ohci_platform_init 178110
SUM193178

So, the idea is that the startup improvement of rcar_i2c_driver_init()
comes at the cost of a slower cs2000_driver_init(). In the end,
there is no benefit and this doesn't work as an argument why the patch
should go upstream.

With regard to the primary argument, that the proposed patch
reduces/minimizes the boot time variance when switching certain drivers
like rcar-du from synchronous to asynchronous probing, I can clearly
sense this in my measurements, but I'm afraid I won't be able to provide
a simple and comprehensive explanation why this happens, since we
enter the territory of concurrent/parallel driver initialization.

If evidence in the form of measurements showing improved behavior
is not enough for the patch to be accepted, then we have no choice but
to keep the patch out-of-tree as a "workaround", hoping that we'll be able
to come up with a better/cleaner solution in future.

If you ever stumble upon a mailing list discussing how to "stabilize"
the boot time as a consequence of using asynchronous probing, then
please drop a link and this will be appreciated.

Many thanks,
Eugeniu.

Re: [PATCH] i2c: rcar: initialize earlier using subsys_initcall()

[Wolfram Sang]

> Thus putting an I2C master controller device driver to the same late
> init level means that due to the concurrency there will be lots of
> probe defers of endpoint device drivers, and making "heavy" device
> drivers like rcar-vin to be run in asyncronous probe increases boot
> time dispersion (rcar-vin is already probed, it's time to probe a
> sensor, but I2C controller is not yet ready to operate, defer).

I do understand the problem. Yet, the root casue is that deferred
probing is only an interim solution not well suited for such cases.

> I don't suppose that the proposed change has any single negative
> side effect, well, right, probe/remove code becomes more awkward,
> but in general the expected effect to boot time improvement should
> cover it, I hope.

We once had a discussion where one guy needed subsys_initcall and the
other one needed module_init because of different use cases. That was
not great.

I am fully aware some probe ordering solution in Linux is much desired.
But fine-tuning init levels is a workaround. Even worse, it will
reduce the pressure for a proper solution. And if we ever get that
solution, different init levels will likely make the conversion harder.

So, I do understand your customers want such a patch for their use case.
But I don't think it is a good idea for the upstream kernel.

I'd think this is an out-of-tree patch for now. I'll talk with some
other people about their view, but I remain very sceptic.

> >> Another effect seems to be improving the init time of rcar_i2c_driver
> >> itself from ~7ms to ~1ms (assuming CONFIG_I2C_RCAR=y).
> > 
> > That doesn't help the patch much ;), but still interesting because I didn't
> > expect that. Do you have an idea why?

Still interested.



signature.asc
Description: PGP signature

Re: [PATCH] i2c: rcar: initialize earlier using subsys_initcall()

[Vladimir Zapolskiy]

Hi Wolfram,

On 04/03/2018 06:55 PM, Wolfram Sang wrote:
> Hi Vladimir and Eugeniu,
> 
>> The purpose of this patch looks pretty similar to:
>> 104522806a7d ("i2c: designware: dw_i2c_init_driver as subsys initcall")
>> 74f56c4ad4e4 ("i2c-bfin-twi: move setup to the earlier subsys initcall")
>> b8680784875b ("i2c-gpio: Move initialization code to subsys_initcall()")
>> 5d3f33318a6c ("[PATCH] i2c-imx: make bus available early")
>> ccb3bc16b489 ("i2c-sh_mobile: change module_init() to subsys_initcall()")
>> 18dc83a6ea48 ("i2c: i2c-s3c2410: Initialise Samsung I2C controller early")
>> 2514cca06be9 ("[ARM] 5394/1: Add static bus numbering support to 
>> i2c-versatile")
>> 47a9b1379a5e ("i2c-pxa: Initialize early")
>>
>> However, the story behind it might be a bit different.
> 
> It definately is. The above drivers are very old, from the days where
> -EPROBE_DEFER was non-existant. They needed subsys_initcall to be able
> to boot. The reason they still have it is simple: reverting to
> module_initcall could cause regressions.
> 
> This patch is about boot-time. Very different.
> 
>> Experimenting with async probing in various rcar-specific drivers (e.g.
>> rcar-du, vsp1, rcar-fcp, rcar-vin), it was noticed that in most of
>> the cases enabling async probing in one driver introduced some degree of
>> inconsistency in the initialization of other builtin drivers.
> 
> I have to admit I never played with async probing...
> 
>> To give an example, with pure sequential driver initialization, based
>> on 5 dmesg logs, the builtin kernel initialization deviation is
>> around +/- 5ms, whereas after enabling async probing in e.g. vsp1
>> driver, the variance is increased to sometimes +/- 80ms or more.
> 
> ... so I can't tell if there is something which can be fixed on the
> async probe side. I would naively think so.
> 
>> This patch fixes it and keeps the startup time consistent after
>> switching certain i2c-dependent drivers to asynchronous probing on
>> H3-es20-Salvator-X target.
> 
> I am not convinced "fix" is the right word here. Why is it not just a
> workaround? Are there no other possibilities? I know other solutions are
> usually complicated, but playing with init levels is fragile and caused
> circular dependencies in the past, so I really don't like them.

in summary (and according to my understanding, Eugeniu please feel free
to correct me) the actual product boards have multitude of I2C devices
connected to the master controller. It requires to read EDID to enable
video output or init sensors to get video input and so on, and normally
device drivers of endpoint devices are executed on module_init() level.

Thus putting an I2C master controller device driver to the same late
init level means that due to the concurrency there will be lots of
probe defers of endpoint device drivers, and making "heavy" device
drivers like rcar-vin to be run in asyncronous probe increases boot
time dispersion (rcar-vin is already probed, it's time to probe a
sensor, but I2C controller is not yet ready to operate, defer).

I don't suppose that the proposed change has any single negative
side effect, well, right, probe/remove code becomes more awkward,
but in general the expected effect to boot time improvement should
cover it, I hope.

>> Another effect seems to be improving the init time of rcar_i2c_driver
>> itself from ~7ms to ~1ms (assuming CONFIG_I2C_RCAR=y).
> 
> That doesn't help the patch much ;), but still interesting because I didn't
> expect that. Do you have an idea why?
> 

--
With best wishes,
Vladimir

Re: [PATCH] i2c: rcar: initialize earlier using subsys_initcall()

[Wolfram Sang]

Hi Vladimir and Eugeniu,

> The purpose of this patch looks pretty similar to:
> 104522806a7d ("i2c: designware: dw_i2c_init_driver as subsys initcall")
> 74f56c4ad4e4 ("i2c-bfin-twi: move setup to the earlier subsys initcall")
> b8680784875b ("i2c-gpio: Move initialization code to subsys_initcall()")
> 5d3f33318a6c ("[PATCH] i2c-imx: make bus available early")
> ccb3bc16b489 ("i2c-sh_mobile: change module_init() to subsys_initcall()")
> 18dc83a6ea48 ("i2c: i2c-s3c2410: Initialise Samsung I2C controller early")
> 2514cca06be9 ("[ARM] 5394/1: Add static bus numbering support to 
> i2c-versatile")
> 47a9b1379a5e ("i2c-pxa: Initialize early")
> 
> However, the story behind it might be a bit different.

It definately is. The above drivers are very old, from the days where
-EPROBE_DEFER was non-existant. They needed subsys_initcall to be able
to boot. The reason they still have it is simple: reverting to
module_initcall could cause regressions.

This patch is about boot-time. Very different.

> Experimenting with async probing in various rcar-specific drivers (e.g.
> rcar-du, vsp1, rcar-fcp, rcar-vin), it was noticed that in most of
> the cases enabling async probing in one driver introduced some degree of
> inconsistency in the initialization of other builtin drivers.

I have to admit I never played with async probing...

> To give an example, with pure sequential driver initialization, based
> on 5 dmesg logs, the builtin kernel initialization deviation is
> around +/- 5ms, whereas after enabling async probing in e.g. vsp1
> driver, the variance is increased to sometimes +/- 80ms or more.

... so I can't tell if there is something which can be fixed on the
async probe side. I would naively think so.

> This patch fixes it and keeps the startup time consistent after
> switching certain i2c-dependent drivers to asynchronous probing on
> H3-es20-Salvator-X target.

I am not convinced "fix" is the right word here. Why is it not just a
workaround? Are there no other possibilities? I know other solutions are
usually complicated, but playing with init levels is fragile and caused
circular dependencies in the past, so I really don't like them.

> Another effect seems to be improving the init time of rcar_i2c_driver
> itself from ~7ms to ~1ms (assuming CONFIG_I2C_RCAR=y).

That doesn't help the patch much ;), but still interesting because I didn't
expect that. Do you have an idea why?

Regards,

   Wolfram



signature.asc
Description: PGP signature

Re: [PATCH] i2c: rcar: initialize earlier using subsys_initcall()

[Eugeniu Rosca]

Hello Wolfram and i2c/Renesas contributors,

To give you some background behind this change, it is done in the
context of rcar3 boot optimization, while trying to put our past
experience in practice for reaching the "rvc-in-less-than-2s"
requirement for our customers.

The current commit description should already speak by itself. While
switching drivers to async probing is hardly suitable with mainline
(am I wrong?), I believe this small change should be harmless. If
there are any concerns, we will do our best to properly handle them.

Special thanks to Vladimir, for reviewing and submitting the patch.

Best regards,
Eugeniu.

On Fri, Mar 16, 2018 at 12:58:52PM +0200, Vladimir Zapolskiy wrote:
> From: Eugeniu Rosca 
> 
> The purpose of this patch looks pretty similar to:
> 104522806a7d ("i2c: designware: dw_i2c_init_driver as subsys initcall")
> 74f56c4ad4e4 ("i2c-bfin-twi: move setup to the earlier subsys initcall")
> b8680784875b ("i2c-gpio: Move initialization code to subsys_initcall()")
> 5d3f33318a6c ("[PATCH] i2c-imx: make bus available early")
> ccb3bc16b489 ("i2c-sh_mobile: change module_init() to subsys_initcall()")
> 18dc83a6ea48 ("i2c: i2c-s3c2410: Initialise Samsung I2C controller early")
> 2514cca06be9 ("[ARM] 5394/1: Add static bus numbering support to 
> i2c-versatile")
> 47a9b1379a5e ("i2c-pxa: Initialize early")
> 
> However, the story behind it might be a bit different.
> Experimenting with async probing in various rcar-specific drivers (e.g.
> rcar-du, vsp1, rcar-fcp, rcar-vin), it was noticed that in most of
> the cases enabling async probing in one driver introduced some degree of
> inconsistency in the initialization of other builtin drivers.
> 
> To give an example, with pure sequential driver initialization, based
> on 5 dmesg logs, the builtin kernel initialization deviation is
> around +/- 5ms, whereas after enabling async probing in e.g. vsp1
> driver, the variance is increased to sometimes +/- 80ms or more.
> 
> This patch fixes it and keeps the startup time consistent after
> switching certain i2c-dependent drivers to asynchronous probing on
> H3-es20-Salvator-X target.
> 
> Another effect seems to be improving the init time of rcar_i2c_driver
> itself from ~7ms to ~1ms (assuming CONFIG_I2C_RCAR=y).
> 
> Signed-off-by: Eugeniu Rosca 
> Signed-off-by: Vladimir Zapolskiy 
> ---
>  drivers/i2c/busses/i2c-rcar.c | 13 -
>  1 file changed, 12 insertions(+), 1 deletion(-)
> 
> diff --git a/drivers/i2c/busses/i2c-rcar.c b/drivers/i2c/busses/i2c-rcar.c
> index 4159ebcec2bb..502f62052b49 100644
> --- a/drivers/i2c/busses/i2c-rcar.c
> +++ b/drivers/i2c/busses/i2c-rcar.c
> @@ -972,7 +972,18 @@ static struct platform_driver rcar_i2c_driver = {
>   .remove = rcar_i2c_remove,
>  };
>  
> -module_platform_driver(rcar_i2c_driver);
> +static int __init rcar_i2c_driver_init(void)
> +{
> + return platform_driver_register(_i2c_driver);
> +}
> +
> +static void __exit rcar_i2c_driver_exit(void)
> +{
> + return platform_driver_unregister(_i2c_driver);
> +}
> +
> +subsys_initcall(rcar_i2c_driver_init);
> +module_exit(rcar_i2c_driver_exit);
>  
>  MODULE_LICENSE("GPL v2");
>  MODULE_DESCRIPTION("Renesas R-Car I2C bus driver");
> -- 
> 2.8.1
> 

Best regards,
Eugeniu.