kernel: init: allow to jitter boot delay #25627

markus-becker-tridonic-com · 2020-05-26T14:31:11Z

When a big amount of networked devices collectively gets switched on,
e.g. by a mains switch, quickly overwhelms a wireless network.

This PR allows to jitter the start-up of the devices.

Cleaned-up the boot banner after the boot delay. At that point in time
is irrelevant.

Signed-off-by: Markus Becker markus.becker@tridonic.com

markus-becker-tridonic-com · 2020-05-26T14:32:32Z

Open issue: How to make sure that the printk() is flushed before k_msleep()?

pfalcon · 2020-05-26T15:59:48Z

When a big amount of networked devices collectively gets switched on,
e.g. by a mains switch, quickly overwhelms a wireless network.

As this mentions networking usecase, adding @jukkar to reviewers. I myself would point that if networking is the usecase, than rather e.g. DHCP client should have a randomized delay support. Handling that with a boot delay seems like a crude approach.

markus-becker-tridonic-com · 2020-05-27T06:03:12Z

It is mostly a wireless/BT/openThread networking use case, not all of the networking options necessarily require DHCP.

It might be a crude approach, but the implementation is rather straight forward.

jukkar

Looks reasonable. And as already commented, the DHCP provides similar support but if one is not using DHCP then something like this is useful.

kernel/Kconfig

kernel/init.c

markus-becker-tridonic-com · 2020-06-08T13:52:58Z

rebased on master post 2.3 release.

markus-becker-tridonic-com · 2020-06-30T14:06:24Z

@jukkar @andyross would you take yet another look at this reworked solution?

kernel/init.c

andyross

Nitpick about docs, but one that does need to be fixed. Also confused about that noop printk wrapper.

andyross · 2020-07-06T17:18:45Z

kernel/Kconfig

+	help
+	  This option randomizes the bootup delay between 0 and the
+	  value of BOOT_DELAY. This can be used e.g., to jitter boot-up
+	  of wireless network devices.


Pedantry: this needs to specify units. How long is "1"? One reasonable choice IMHO is to bake it into the API and call this CONFIG_BOOT_DELAY_RANDOM_MS

As it says, the value is between 0 and BOOT_DELAY. BOOT_DELAY is in milliseconds:
https://github.com/zephyrproject-rtos/zephyr/pull/25627/files#diff-a0dbba97dac305f5927e75a408d79a25R309-R310

andyross · 2020-07-06T17:19:18Z

kernel/init.c

+	va_start(ap, fmt);
+	vprintk(fmt, ap);
+	va_end(ap);
+}


I don't get it. What is the point of this?

printk() is calling log_printk() when CONFIG_LOG_PRINTK is on. Then the output would be happening in the logging thread which is halted while the busy-loop is running. The output of the delay would only happen after the delay and thus leaving the user wondering what is happening.

This way the message is outputted before the busy-loop executes and the user knows that boot is delayed.

ceolin · 2020-07-06T17:21:04Z

kernel/init.c

@@ -191,6 +182,15 @@ void z_data_copy(void)

 bool z_sys_post_kernel;

+void immediate_printk(const char *fmt, ...)


why are you adding it ? What it the problem with printk ? I presume is something related with log_printk ... but I don't know what it is.

ceolin · 2020-07-06T17:22:49Z

kernel/Kconfig

+	help
+	  This option randomizes the bootup delay between 0 and the
+	  value of BOOT_DELAY. This can be used e.g., to jitter boot-up
+	  of wireless network devices.


It is worth to add a note about it in BOOT_DELAY option. Because there is saying that the entire value set will be used to delay the boot.

If BOOT_DELAY_RANDOM is not set, then BOOT_DELAY is used.

Would you rather add a random delay on top of BOOT_DELAY?

ceolin

Please check my comments. If I'm right the random value is not being used.

andrewboie

I would rather you not modify the core kernel for this use-case.

Have you considered defining a SYS_INIT() in your application (at PRE_KERNEL_1) which just introduces a delay there?

markus-becker-tridonic-com · 2020-07-09T07:06:50Z

I would rather you not modify the core kernel for this use-case.

Have you considered defining a SYS_INIT() in your application (at PRE_KERNEL_1) which just introduces a delay there?

Have not considered this. How would you delay network set-up with SYS_INIT()? Do you have an example?

When a big amount of networked devices collectively gets switched on, e.g. by a mains switch, a low-bandwidth wireless network is quickly overwhelmed. This PR allows to jitter the start-up of the devices. Cleaned-up the boot banner after the boot delay. At that point in time the boot banner is irrelevant. Signed-off-by: Markus Becker <markus.becker@tridonic.com>

andyross · 2020-07-09T14:59:34Z

printk() is calling log_printk() when CONFIG_LOG_PRINTK is on. Then the output would be happening in the logging thread

OK... I get it. And this is clever, but... no, sorry. :)

Really what you're doing here is exploiting a bug in the logging subsystem. CONFIG_LOG_PRINTK is supposed to mean that printk() output goes to logging instead, but apparently the feature missed a spot, or put the hook in the wrong place, and it happens that vprintk() doesn't do that and goes to the original output. But that's wrong. When you have CONFIG_LOG=y and CONFIG_LOG_IMMEDIATE=n, logging is asynchronous. That's the way it's supposed to work, and it's desired behavior[1]. Subsystems shouldn't be silently working around the intended behavior of other subsystems by using backdoors.

Basically: if the user asked for async logging give them what they want. If you don't think they should want that, let's deal with that via a patch to the log layer.

[1] By someone (cough, cough, @nordic-krch). I actually agree that for most development usage asynchronous logging is the devil's work and don't understand why we decided to make it default. But it's the system we have, so let's not hack holes around it.

markus-becker-tridonic-com · 2020-07-13T20:27:38Z

printk() is calling log_printk() when CONFIG_LOG_PRINTK is on. Then the output would be happening in the logging thread

OK... I get it. And this is clever

Thanks :)

, but... no, sorry. :)

Hmm.

Really what you're doing here is exploiting a bug in the logging subsystem. CONFIG_LOG_PRINTK is supposed to mean that printk() output goes to logging instead, but apparently the feature missed a spot, or put the hook in the wrong place, and it happens that vprintk() doesn't do that and goes to the original output. But that's wrong. When you have CONFIG_LOG=y and CONFIG_LOG_IMMEDIATE=n, logging is asynchronous. That's the way it's supposed to work, and it's desired behavior[1]. Subsystems shouldn't be silently working around the intended behavior of other subsystems by using backdoors.

Will the bug be fixed?

Basically: if the user asked for async logging give them what they want. If you don't think they should want that, let's deal with that via a patch to the log layer.

True, that the user wants to use async logging (or has to because it is pulled in by default). But this tripped me several times, looking at debug on UART and expecting to see something, only to notice several trials later that the device is delaying the boot.

For my information, would be switching the logging backend to RTT make any difference?

[1] By someone (cough, cough, @nordic-krch). I actually agree that for most development usage asynchronous logging is the devil's work and don't understand why we decided to make it default. But it's the system we have, so let's not hack holes around it.

What was the reason to move it to async? Would disabling async logging be possible? What would be the side-effects?

andrewboie · 2020-07-13T21:31:58Z

Will the bug be fixed?

Do we have a bug opened on GitHub for this issue? That's the first step.

Consider enabling CONFIG_LOG_MINIMAL and just ignoring the async log mechanism.

github-actions · 2020-09-12T00:58:58Z

This pull request has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this pull request will automatically be closed in 14 days. Note, that you can always re-open a closed pull request at any time.

markus-becker-tridonic-com requested review from andrewboie and andyross as code owners May 26, 2020 14:31

zephyrbot added the area: Kernel label May 26, 2020

pfalcon requested a review from jukkar May 26, 2020 15:56

jukkar requested changes May 27, 2020

View reviewed changes

kernel/Kconfig Outdated Show resolved Hide resolved

kernel/Kconfig Outdated Show resolved Hide resolved

kernel/init.c Outdated Show resolved Hide resolved

markus-becker-tridonic-com force-pushed the jitter-boot-delay branch from c4978f7 to 6d8db01 Compare May 27, 2020 06:53

Philipp-Wohlgenannt-Tridonic-com mentioned this pull request Jun 4, 2020

net: openthread: add pskd join loop #25589

Closed

markus-becker-tridonic-com force-pushed the jitter-boot-delay branch from 6d8db01 to cce769a Compare June 8, 2020 13:43

markus-becker-tridonic-com force-pushed the jitter-boot-delay branch from cce769a to b14f096 Compare June 15, 2020 11:42

markus-becker-tridonic-com requested a review from jukkar June 22, 2020 06:36

markus-becker-tridonic-com force-pushed the jitter-boot-delay branch from b14f096 to e904700 Compare June 30, 2020 14:04

markus-becker-tridonic-com force-pushed the jitter-boot-delay branch from e904700 to 0f8096b Compare July 1, 2020 06:49

stephanosio self-requested a review July 6, 2020 14:03

carlescufi requested a review from ceolin July 6, 2020 14:12

ceolin reviewed Jul 6, 2020

View reviewed changes

kernel/init.c Outdated Show resolved Hide resolved

andyross requested changes Jul 6, 2020

View reviewed changes

ceolin reviewed Jul 6, 2020

View reviewed changes

ceolin requested changes Jul 6, 2020

View reviewed changes

andrewboie suggested changes Jul 6, 2020

View reviewed changes

markus-becker-tridonic-com force-pushed the jitter-boot-delay branch from 0f8096b to 4640172 Compare July 9, 2020 07:05

markus-becker-tridonic-com force-pushed the jitter-boot-delay branch from 4640172 to 63f83af Compare July 9, 2020 07:26

github-actions bot added the Stale label Sep 12, 2020

github-actions bot closed this Sep 26, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

kernel: init: allow to jitter boot delay #25627

kernel: init: allow to jitter boot delay #25627

markus-becker-tridonic-com commented May 26, 2020

markus-becker-tridonic-com commented May 26, 2020 •

edited

pfalcon commented May 26, 2020

markus-becker-tridonic-com commented May 27, 2020

jukkar left a comment

markus-becker-tridonic-com commented Jun 8, 2020

markus-becker-tridonic-com commented Jun 30, 2020

andyross left a comment

andyross Jul 6, 2020

markus-becker-tridonic-com Jul 9, 2020

andyross Jul 6, 2020

markus-becker-tridonic-com Jul 9, 2020

ceolin Jul 6, 2020

markus-becker-tridonic-com Jul 9, 2020

ceolin Jul 6, 2020

markus-becker-tridonic-com Jul 9, 2020

ceolin left a comment

andrewboie left a comment

markus-becker-tridonic-com commented Jul 9, 2020

andyross commented Jul 9, 2020 •

edited

markus-becker-tridonic-com commented Jul 13, 2020

andrewboie commented Jul 13, 2020 •

edited

github-actions bot commented Sep 12, 2020

		@@ -191,6 +182,15 @@ void z_data_copy(void)

		bool z_sys_post_kernel;

		void immediate_printk(const char *fmt, ...)

kernel: init: allow to jitter boot delay #25627

kernel: init: allow to jitter boot delay #25627

Conversation

markus-becker-tridonic-com commented May 26, 2020

markus-becker-tridonic-com commented May 26, 2020 • edited

pfalcon commented May 26, 2020

markus-becker-tridonic-com commented May 27, 2020

jukkar left a comment

Choose a reason for hiding this comment

markus-becker-tridonic-com commented Jun 8, 2020

markus-becker-tridonic-com commented Jun 30, 2020

andyross left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ceolin left a comment

Choose a reason for hiding this comment

andrewboie left a comment

Choose a reason for hiding this comment

markus-becker-tridonic-com commented Jul 9, 2020

andyross commented Jul 9, 2020 • edited

markus-becker-tridonic-com commented Jul 13, 2020

andrewboie commented Jul 13, 2020 • edited

github-actions bot commented Sep 12, 2020

markus-becker-tridonic-com commented May 26, 2020 •

edited

andyross commented Jul 9, 2020 •

edited

andrewboie commented Jul 13, 2020 •

edited