Topics

ttyS0 timeout but not using ttyS0 #yocto #systemd


William Durocher
 

We have a build using warrior it boots up well but has a very long boot time of around 95 sec. Using systemd-analyze I notice that we the boot takes a long time before getting to multi-user.target. As can be seen for the critical chain analysis below, there is a 60s gap after we get our console on ttyO0.
multi-user.target @1min 33.351s
└─getty.target @1min 33.298s
  └─serial-getty@... @34.432s
    └─basic.target @31.841s
      └─sockets.target @31.804s
        └─sshd.socket @31.532s +238ms
          └─sysinit.target @31.183s
            └─sys-kernel-config.mount @59.350s +962ms
              └─systemd-journald.socket @2.553s
                └─system.slice @2.027s
                  └─-.slice @2.028s

Looking at the logs I can see that the cause is most likely that ttyS0 is trying to come up.
Jan 27 01:07:14 rc8000-5e2b systemd[1]: dev-ttyS0.device: Job dev-ttyS0.device/start
 timed out.                                                                        
Jan 27 01:07:14 rc8000-5e2b systemd[1]: Timed out waiting for device /dev/ttyS0.   
Jan 27 01:07:14 rc8000-5e2b systemd[1]: Dependency failed for Serial Getty on ttyS0.
Jan 27 01:07:14 rc8000-5e2b systemd[1]: serial-getty@...: Job serial-getty
@ttyS0.service/start failed with result 'dependency'.                              
Jan 27 01:07:14 rc8000-5e2b systemd[1]: dev-ttyS0.device: Job dev-ttyS0.device/start
 failed with result 'timeout'.                                                     
Jan 27 01:07:14 rc8000-5e2b systemd[1]: dev-ttyS0.device: Job dev-ttyS0.device/start
 timed out.                                                                        
Jan 27 01:07:14 rc8000-5e2b systemd[1]: Timed out waiting for device /dev/ttyS0.   
Jan 27 01:07:14 rc8000-5e2b systemd[1]: Dependency failed for Serial Getty on ttyS0.
Jan 27 01:07:14 rc8000-5e2b systemd[1]: serial-getty@...: Job serial-getty
@ttyS0.service/start failed with result 'dependency'.                              
Jan 27 01:07:14 rc8000-5e2b systemd[1]: dev-ttyS0.device: Job dev-ttyS0.device/start
 failed with result 'timeout'.                                                     
Jan 27 01:07:15 rc8000-5e2b systemd[1]: dev-ttyS0.device: Job dev-ttyS0.device/start
 timed out.                                                                        
Jan 27 01:07:15 rc8000-5e2b systemd[1]: Timed out waiting for device /dev/ttyS0.   
Jan 27 01:07:15 rc8000-5e2b systemd[1]: Dependency failed for Serial Getty on ttyS0.
Jan 27 01:07:15 rc8000-5e2b systemd[1]: serial-getty@...: Job serial-getty
@ttyS0.service/start failed with result 'dependency'.                              
Jan 27 01:07:15 rc8000-5e2b systemd[1]: dev-ttyS0.device: Job dev-ttyS0.device/start
 failed with result 'timeout'.                                                     
Jan 27 01:07:15 rc8000-5e2b systemd[1]: dev-ttyS0.device: Job dev-ttyS0.device/start
 timed out.                                                                        
Jan 27 01:07:15 rc8000-5e2b systemd[1]: Timed out waiting for device /dev/ttyS0.   
Jan 27 01:07:15 rc8000-5e2b systemd[1]: Dependency failed for Serial Getty on ttyS0.
Jan 27 01:07:15 rc8000-5e2b systemd[1]: serial-getty@...: Job serial-getty
@ttyS0.service/start failed with result 'dependency'.                              
Jan 27 01:07:15 rc8000-5e2b systemd[1]:

We are not using ttyS0 for the console or anything. In our distro config and layer we refer instead to ttyO0.

Looking through the environment of the build with "bitbake -e our-image" I see that we had
# $KERNEL_CONSOLE
#   set? /home/wdurocher/work/gammaip/warrior/sources/meta/meta/conf/distro/include/default-distrovars.inc:4
#     "ttyS0"
KERNEL_CONSOLE="ttyS0"
 I modifed our distro configuration setting KERNEL_MODULE to ttyO0
KERNEL_CONSOLE="ttyO0"
and now bitbake -e gives me:
# $KERNEL_CONSOLE [2 operations]
#   set /home/wdurocher/work/gammaip/warrior/sources/meta-gammaip/conf/distro/gammaip.conf:18
#     "ttyO0"
#   set? /home/wdurocher/work/gammaip/warrior/sources/meta/meta/conf/distro/include/default-distrovars.inc:4
#     "ttyS0"
# pre-expansion value:
#   "ttyO0"
KERNEL_CONSOLE="ttyO0"
But loading this image, the logs still shows the timeout waiting for ttyS0. What else could be making Linux try to configure ttyS0 ?

Note that I saw in my search that kernel CONFIG_FHANDLE should be set and it was already so.

Thanking you for any help on this,

William Durocher


Khem Raj
 

On Mon, Jan 27, 2020 at 12:16 PM William Durocher <wdurocher@it-link.ca> wrote:

We have a build using warrior it boots up well but has a very long boot time of around 95 sec. Using systemd-analyze I notice that we the boot takes a long time before getting to multi-user.target. As can be seen for the critical chain analysis below, there is a 60s gap after we get our console on ttyO0.

multi-user.target @1min 33.351s
└─getty.target @1min 33.298s
└─serial-getty@ttyO0.service @34.432s
└─basic.target @31.841s
└─sockets.target @31.804s
└─sshd.socket @31.532s +238ms
└─sysinit.target @31.183s
└─sys-kernel-config.mount @59.350s +962ms
└─systemd-journald.socket @2.553s
└─system.slice @2.027s
└─-.slice @2.028s


Looking at the logs I can see that the cause is most likely that ttyS0 is trying to come up.

Jan 27 01:07:14 rc8000-5e2b systemd[1]: dev-ttyS0.device: Job dev-ttyS0.device/start
timed out.
Jan 27 01:07:14 rc8000-5e2b systemd[1]: Timed out waiting for device /dev/ttyS0.
Jan 27 01:07:14 rc8000-5e2b systemd[1]: Dependency failed for Serial Getty on ttyS0.
Jan 27 01:07:14 rc8000-5e2b systemd[1]: serial-getty@ttyS0.service: Job serial-getty
@ttyS0.service/start failed with result 'dependency'.
Jan 27 01:07:14 rc8000-5e2b systemd[1]: dev-ttyS0.device: Job dev-ttyS0.device/start
failed with result 'timeout'.
Jan 27 01:07:14 rc8000-5e2b systemd[1]: dev-ttyS0.device: Job dev-ttyS0.device/start
timed out.
Jan 27 01:07:14 rc8000-5e2b systemd[1]: Timed out waiting for device /dev/ttyS0.
Jan 27 01:07:14 rc8000-5e2b systemd[1]: Dependency failed for Serial Getty on ttyS0.
Jan 27 01:07:14 rc8000-5e2b systemd[1]: serial-getty@ttyS0.service: Job serial-getty
@ttyS0.service/start failed with result 'dependency'.
Jan 27 01:07:14 rc8000-5e2b systemd[1]: dev-ttyS0.device: Job dev-ttyS0.device/start
failed with result 'timeout'.
Jan 27 01:07:15 rc8000-5e2b systemd[1]: dev-ttyS0.device: Job dev-ttyS0.device/start
timed out.
Jan 27 01:07:15 rc8000-5e2b systemd[1]: Timed out waiting for device /dev/ttyS0.
Jan 27 01:07:15 rc8000-5e2b systemd[1]: Dependency failed for Serial Getty on ttyS0.
Jan 27 01:07:15 rc8000-5e2b systemd[1]: serial-getty@ttyS0.service: Job serial-getty
@ttyS0.service/start failed with result 'dependency'.
Jan 27 01:07:15 rc8000-5e2b systemd[1]: dev-ttyS0.device: Job dev-ttyS0.device/start
failed with result 'timeout'.
Jan 27 01:07:15 rc8000-5e2b systemd[1]: dev-ttyS0.device: Job dev-ttyS0.device/start
timed out.
Jan 27 01:07:15 rc8000-5e2b systemd[1]: Timed out waiting for device /dev/ttyS0.
Jan 27 01:07:15 rc8000-5e2b systemd[1]: Dependency failed for Serial Getty on ttyS0.
Jan 27 01:07:15 rc8000-5e2b systemd[1]: serial-getty@ttyS0.service: Job serial-getty
@ttyS0.service/start failed with result 'dependency'.
Jan 27 01:07:15 rc8000-5e2b systemd[1]:
what is SERIAL_CONSOLES variable set to ? this should be machine setting.


We are not using ttyS0 for the console or anything. In our distro config and layer we refer instead to ttyO0.

Looking through the environment of the build with "bitbake -e our-image" I see that we had

# $KERNEL_CONSOLE
# set? /home/wdurocher/work/gammaip/warrior/sources/meta/meta/conf/distro/include/default-distrovars.inc:4
# "ttyS0"
KERNEL_CONSOLE="ttyS0"

I modifed our distro configuration setting KERNEL_MODULE to ttyO0

KERNEL_CONSOLE="ttyO0"

and now bitbake -e gives me:

# $KERNEL_CONSOLE [2 operations]
# set /home/wdurocher/work/gammaip/warrior/sources/meta-gammaip/conf/distro/gammaip.conf:18
# "ttyO0"
# set? /home/wdurocher/work/gammaip/warrior/sources/meta/meta/conf/distro/include/default-distrovars.inc:4
# "ttyS0"
# pre-expansion value:
# "ttyO0"
KERNEL_CONSOLE="ttyO0"

But loading this image, the logs still shows the timeout waiting for ttyS0. What else could be making Linux try to configure ttyS0 ?

Note that I saw in my search that kernel CONFIG_FHANDLE should be set and it was already so.

Thanking you for any help on this,

William Durocher


William Durocher
 

Thank you for the quick reply,
 in our machin confif only SERIAL_CONSOLE is set, it is:
SERIAL_CONSOLE = "115200 ttyO0"
But yocto then uses that to set SERIAL_CONSOLES

In bitbake -e I see SERIAL_CONSOLE and SERIAL_CONSOLES set to :
# $SERIAL_CONSOLE [3 operations]
#   set /home/wdurocher/work/gammaip/warrior/sources/meta-gammaip/conf/machine/gammaip.conf:16
#     "115200 ttyO0"
#   set /home/wdurocher/work/gammaip/warrior/sources/meta/meta/conf/documentation.conf:371
#     [doc] "The speed and device for the serial port used to attach the serial console. This variable is given to the kernel as the 'console' parameter. After booting occurs, getty is started on that port so remote login is possible."
#   set /home/wdurocher/work/gammaip/warrior/sources/meta/meta/conf/bitbake.conf:845
#     [_defaultval] ""
# pre-expansion value:
#   "115200 ttyO0"
SERIAL_CONSOLE="115200 ttyO0"
#
# $SERIAL_CONSOLES [2 operations]
#   set /home/wdurocher/work/gammaip/warrior/sources/meta/meta/conf/documentation.conf:372
#     [doc] "Defines the serial consoles (TTYs) to enable using getty."
#   set /home/wdurocher/work/gammaip/warrior/sources/meta/meta/conf/bitbake.conf:846
#     [_defaultval] "${@d.getVar('SERIAL_CONSOLE').replace(' ', ';')}"
# pre-expansion value:
#   "${@d.getVar('SERIAL_CONSOLE').replace(' ', ';')}"
SERIAL_CONSOLES="115200;ttyO0"


William Durocher
 

Got it figured out, Seems that the default values from meta/recipes-core/systemd/systemd-serialgetty.bb for SERIAL_CONSOLES in are being processed instead of the expansion in our layer. Even though SERIAL_CONSOLES is using SERIAL_CONSOLE. Our solution is to declare SERIAL_CONSOLE and SERIAL_CONSOLES in our machine config.