Sample Header Ad - 728x90

Boot Delays on PowerPC Board with RTC Clock and hwclock --hctosys Command Related to Kernel Configurations

0 votes
0 answers
29 views
I am working on a PowerPC board using kernel version 4.1.35 and encountering significant boot **delays**, specifically around the RTC clock (ds-1337) operations. During the boot process, a script (hwclock.sh) runs the hwclock --hctosys command, and I've added print statements to log its execution time in the kernel logs. Here’s a snippet from hwclock.sh: echo "running command hwclock --hctosys. - arij" | tee /dev/kmsg hwclock $tz --hctosys echo "ending hwclock --hctosys. - arij" | tee /dev/kmsg When the kernel configuration CONFIG_DYNAMIC_DEBUG is disabled, the hwclock command experiences significant delays, sometimes up to 50 seconds. However, when **CONFIG_DYNAMIC_DEBUG** is enabled, the delays are significantly reduced, with execution times ranging between 4 to 12 seconds. Here are some kernel log snippets from various boot cycles with **CONFIG_DYNAMIC_DEBUG** disabled: **Boot cycle 1:**
[    6.401707] running command hwclock --hctosys. - arij
[   39.206200] ending hwclock --hctosys. - arij
**Boot cycle 2:**
[    7.054404] running command hwclock --hctosys. - arij
[   14.218021] ending hwclock --hctosys. - arij
**Boot cycle 5:**
[   18.659482] running command hwclock --hctosys. - arij
[   50.005113] ending hwclock --hctosys. - arij
With CONFIG_DYNAMIC_DEBUG enabled, the delays decrease: Example with **CONFIG_DYNAMIC_DEBUG **enabled:
[   8.833980] running command hwclock --hctosys. - arij
[  14.223970] ending hwclock --hctosys. - arij
Additionally, when booting with the configuration CONFIG_PROFILING enabled, the hwclock command consistently takes no more than 2 seconds. **Questions** 1. What could be causing the drastic increase in boot time when CONFIG_DYNAMIC_DEBUG is disabled? 1. Why does enabling CONFIG_DYNAMIC_DEBUG reduce the time taken for the hwclock --hctosys command? 1. Could there be any underlying issues with the RTC driver or interactions between the hwclock command and kernel configurations? 1. How might CONFIG_PROFILING impact the timing of hwclock --hctosys? 1. Any insights into these behaviors would be greatly appreciated. **Update 1:** i have tried multiple kernel prints in the rtc drivers and it only showed that the mutex lock is waiting to be acquired. i cant understand whats causing the problem and how is it not appearing when dynamic debugging is enabled the prints i enabled are like this: pr_info("--------------------- %s: %s: Line %d - Mutex Locking interruptible - arij\n", __FILE__, __func__, __LINE__); int err = mutex_lock_interruptible(&rtc->ops_lock); pr_info("--------------------- %s: %s: Line %d - Mutex Locked interruptible - arij\n", __FILE__, __func__, __LINE__); and got prints: [ 17.450075] running command hwclock --hctosys. - arij [ 17.461239] rtc_core: --------------------- /home/pc/kernel-source/drivers/rtc/rtc-dev.c: rtc_dev_ioctl: Line 234 - Mutex locking- arij [ 23.737863] rtc_core: --------------------- /home/pc/kernel-source/drivers/rtc/rtc-dev.c: rtc_dev_ioctl: Line 236 - Mutex locked with cmd=1076129801 - arij [ 23.752437] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_read_time: Line 62 - Mutex Locking interruptible - arij [ 27.005861] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_read_time: Line 65 - Mutex Locked interruptible - arij [ 27.020196] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_read_time: Line 74 - Mutex Unlock interruptible - arij [ 27.034029] rtc_core: --------------------- /home/pc/kernel-source/drivers/rtc/rtc-dev.c: rtc_dev_ioctl: Line 234 - Mutex locking- arij [ 30.637859] rtc_core: --------------------- /home/pc/kernel-source/drivers/rtc/rtc-dev.c: rtc_dev_ioctl: Line 236 - Mutex locked with cmd=536899588 - arij [ 30.652312] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_update_irq_enable: Line 515 - Mutex Locking interruptible - arij [ 34.805855] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_update_irq_enable: Line 517 - Mutex Locked interruptible - arij [ 34.819887] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_update_irq_enable: Line 552 - Mutex unock in out: - arij [ 34.833291] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_update_irq_enable: Line 515 - Mutex Locking interruptible - arij [ 62.173853] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_update_irq_enable: Line 517 - Mutex Locked interruptible - arij [ 62.187884] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_update_irq_enable: Line 552 - Mutex unock in out: - arij [ 62.204506] ending hwclock --hctosys. - arij **Update 2:** I also changed the configuration to not get a timeless kernel. but i still observed the same delays CONFIG_HZ_PERIODIC=y CONFIG_NO_HZ_IDLE not set CONFIG_NO_HZ not set
Asked by Mohammad Arij Kamran (3 rep)
Aug 21, 2024, 07:06 AM
Last activity: Aug 21, 2024, 07:15 AM