From: "Steven Rostedt (VMware)" <[email protected]>
With trace events set before and after the initcall function calls, instead
of having a separate routine for printing out the initcalls when
initcall_debug is specified on the kernel command line, have the code
register a callback to the tracepoints where the initcall trace events are.
This removes the need for having a separate function to do the initcalls as
the tracepoint callbacks can handle the printk. It also includes other
initcalls that are not called by the do_one_initcall() which includes
console and security initcalls.
Signed-off-by: Steven Rostedt (VMware) <[email protected]>
---
init/main.c | 51 +++++++++++++++++++++++++++++++++++----------------
1 file changed, 35 insertions(+), 16 deletions(-)
diff --git a/init/main.c b/init/main.c
index 2af8f2bb5ca8..589d1226016e 100644
--- a/init/main.c
+++ b/init/main.c
@@ -494,6 +494,10 @@ void __init __weak thread_stack_cache_init(void)
void __init __weak mem_encrypt_init(void) { }
+bool initcall_debug;
+core_param(initcall_debug, initcall_debug, bool, 0644);
+static void __init initcall_debug_enable(void);
+
/*
* Set up kernel memory allocators
*/
@@ -615,6 +619,9 @@ asmlinkage __visible void __init start_kernel(void)
/* Trace events are available after this */
trace_init();
+ if (initcall_debug)
+ initcall_debug_enable();
+
context_tracking_init();
/* init some links before init_ISA_irqs() */
early_irq_init();
@@ -731,9 +738,6 @@ static void __init do_ctors(void)
#endif
}
-bool initcall_debug;
-core_param(initcall_debug, initcall_debug, bool, 0644);
-
#ifdef CONFIG_KALLSYMS
struct blacklist_entry {
struct list_head next;
@@ -803,38 +807,53 @@ static bool __init_or_module initcall_blacklisted(initcall_t fn)
#endif
__setup("initcall_blacklist=", initcall_blacklist);
-static int __init_or_module do_one_initcall_debug(initcall_t fn)
+static __init_or_module void
+trace_initcall_start_cb(void *data, initcall_t fn)
{
- ktime_t calltime, delta, rettime;
- unsigned long long duration;
- int ret;
+ ktime_t *calltime = (ktime_t *)data;
printk(KERN_DEBUG "calling %pF @ %i\n", fn, task_pid_nr(current));
- calltime = ktime_get();
- ret = fn();
+ *calltime = ktime_get();
+}
+
+static __init_or_module void
+trace_initcall_finish_cb(void *data, initcall_t fn, int ret)
+{
+ ktime_t *calltime = (ktime_t *)data;
+ ktime_t delta, rettime;
+ unsigned long long duration;
+
rettime = ktime_get();
- delta = ktime_sub(rettime, calltime);
+ delta = ktime_sub(rettime, *calltime);
duration = (unsigned long long) ktime_to_ns(delta) >> 10;
printk(KERN_DEBUG "initcall %pF returned %d after %lld usecs\n",
fn, ret, duration);
+}
- return ret;
+static ktime_t initcall_calltime;
+
+static void __init initcall_debug_enable(void)
+{
+ int ret;
+
+ ret = register_trace_initcall_start(trace_initcall_start_cb,
+ &initcall_calltime);
+ ret |= register_trace_initcall_finish(trace_initcall_finish_cb,
+ &initcall_calltime);
+ WARN(ret, "Failed to register initcall tracepoints\n");
}
int __init_or_module do_one_initcall(initcall_t fn)
{
int count = preempt_count();
- int ret;
char msgbuf[64];
+ int ret;
if (initcall_blacklisted(fn))
return -EPERM;
trace_initcall_start(fn);
- if (initcall_debug)
- ret = do_one_initcall_debug(fn);
- else
- ret = fn();
+ ret = fn();
trace_initcall_finish(fn, ret);
msgbuf[0] = 0;
--
2.15.1
FYI, we noticed the following commit (built with gcc-7):
commit: 2580d6b795e25879c825a0891cf67390f665b11f ("init, tracing: Have printk come through the trace events for initcall_debug")
url: https://github.com/0day-ci/linux/commits/Steven-Rostedt/init-tracing/20180407-130743
in testcase: boot
on test machine: qemu-system-x86_64 -enable-kvm -cpu Nehalem -smp 2 -m 512M
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+------------------------------------------------------------------+------------+------------+
| | ecf6709d07 | 2580d6b795 |
+------------------------------------------------------------------+------------+------------+
| boot_successes | 0 | 0 |
| boot_failures | 8 | 8 |
| invoked_oom-killer:gfp_mask=0x | 8 | |
| Mem-Info | 8 | |
| Kernel_panic-not_syncing:Out_of_memory_and_no_killable_processes | 8 | |
| BUG:kernel_reboot-without-warning_in_boot_stage | 0 | 8 |
+------------------------------------------------------------------+------------+------------+
[ 0.000000] RAMDISK: [mem 0x1b7e2000-0x1ffcffff]
[ 0.000000] ACPI: Early table checksum verification disabled
[ 0.000000] ACPI: RSDP 0x00000000000F6860 000014 (v00 BOCHS )
[ 0.000000] ACPI: RSDT 0x000000001FFE1628 000030 (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001)
[ 0.000000] ACPI: FACP 0x000000001FFE147C 000074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001)
BUG: kernel reboot-without-warning in boot stage
Elapsed time: 10
#!/bin/bash
To reproduce:
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
Thanks,
Xiaolong
On Mon, 9 Apr 2018 13:32:52 +0800
kernel test robot <[email protected]> wrote:
> FYI, we noticed the following commit (built with gcc-7):
>
> commit: 2580d6b795e25879c825a0891cf67390f665b11f ("init, tracing: Have printk come through the trace events for initcall_debug")
> url: https://github.com/0day-ci/linux/commits/Steven-Rostedt/init-tracing/20180407-130743
>
>
> in testcase: boot
>
> on test machine: qemu-system-x86_64 -enable-kvm -cpu Nehalem -smp 2 -m 512M
>
> caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
>
>
> +------------------------------------------------------------------+------------+------------+
> | | ecf6709d07 | 2580d6b795 |
> +------------------------------------------------------------------+------------+------------+
> | boot_successes | 0 | 0 |
> | boot_failures | 8 | 8 |
> | invoked_oom-killer:gfp_mask=0x | 8 | |
> | Mem-Info | 8 | |
> | Kernel_panic-not_syncing:Out_of_memory_and_no_killable_processes | 8 | |
> | BUG:kernel_reboot-without-warning_in_boot_stage | 0 | 8 |
> +------------------------------------------------------------------+------------+------------+
What does this mean?
>
>
>
> [ 0.000000] RAMDISK: [mem 0x1b7e2000-0x1ffcffff]
> [ 0.000000] ACPI: Early table checksum verification disabled
> [ 0.000000] ACPI: RSDP 0x00000000000F6860 000014 (v00 BOCHS )
> [ 0.000000] ACPI: RSDT 0x000000001FFE1628 000030 (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001)
> [ 0.000000] ACPI: FACP 0x000000001FFE147C 000074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001)
> BUG: kernel reboot-without-warning in boot stage
>
> Elapsed time: 10
>
> #!/bin/bash
>
>
>
> To reproduce:
>
> git clone https://github.com/intel/lkp-tests.git
> cd lkp-tests
> bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
>
The config boots fine for me. But I don't have the setup to run the
above and get it to work, nor the time to figure out why it doesn't
work.
-- Steve
Hi, Steven
On 04/09, Steven Rostedt wrote:
>On Mon, 9 Apr 2018 13:32:52 +0800
>kernel test robot <[email protected]> wrote:
>
>> FYI, we noticed the following commit (built with gcc-7):
>>
>> commit: 2580d6b795e25879c825a0891cf67390f665b11f ("init, tracing: Have printk come through the trace events for initcall_debug")
>> url: https://github.com/0day-ci/linux/commits/Steven-Rostedt/init-tracing/20180407-130743
>>
>>
>> in testcase: boot
>>
>> on test machine: qemu-system-x86_64 -enable-kvm -cpu Nehalem -smp 2 -m 512M
>>
>> caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
>>
>>
>> +------------------------------------------------------------------+------------+------------+
>> | | ecf6709d07 | 2580d6b795 |
>> +------------------------------------------------------------------+------------+------------+
>> | boot_successes | 0 | 0 |
>> | boot_failures | 8 | 8 |
>> | invoked_oom-killer:gfp_mask=0x | 8 | |
>> | Mem-Info | 8 | |
>> | Kernel_panic-not_syncing:Out_of_memory_and_no_killable_processes | 8 | |
>> | BUG:kernel_reboot-without-warning_in_boot_stage | 0 | 8 |
>> +------------------------------------------------------------------+------------+------------+
>
>What does this mean?
It means BUG:BUG:kernel_reboot-without-warning_in_boot_stage occurred 8 times
in boot tests for commit 2580d6b795, while 0 time for its parent ecf6709d07.
>
>>
>>
>>
>> [ 0.000000] RAMDISK: [mem 0x1b7e2000-0x1ffcffff]
>> [ 0.000000] ACPI: Early table checksum verification disabled
>> [ 0.000000] ACPI: RSDP 0x00000000000F6860 000014 (v00 BOCHS )
>> [ 0.000000] ACPI: RSDT 0x000000001FFE1628 000030 (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001)
>> [ 0.000000] ACPI: FACP 0x000000001FFE147C 000074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001)
>> BUG: kernel reboot-without-warning in boot stage
>>
>> Elapsed time: 10
>>
>> #!/bin/bash
>>
>>
>>
>> To reproduce:
>>
>> git clone https://github.com/intel/lkp-tests.git
>> cd lkp-tests
>> bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
>>
>
>The config boots fine for me. But I don't have the setup to run the
>above and get it to work, nor the time to figure out why it doesn't
>work.
Could you paste your failure log here, we can see if there is something we can help.
Thanks,
Xiaolong
>
>-- Steve
On Tue, 10 Apr 2018 09:23:40 +0800
Ye Xiaolong <[email protected]> wrote:
> Hi, Steven
>
> On 04/09, Steven Rostedt wrote:
> >On Mon, 9 Apr 2018 13:32:52 +0800
> >kernel test robot <[email protected]> wrote:
> >
> >> FYI, we noticed the following commit (built with gcc-7):
> >>
> >> commit: 2580d6b795e25879c825a0891cf67390f665b11f ("init, tracing: Have printk come through the trace events for initcall_debug")
> >> url: https://github.com/0day-ci/linux/commits/Steven-Rostedt/init-tracing/20180407-130743
> >>
> >>
> >> in testcase: boot
> >>
> >> on test machine: qemu-system-x86_64 -enable-kvm -cpu Nehalem -smp 2 -m 512M
> >>
> >> caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
> >>
> >>
> >> +------------------------------------------------------------------+------------+------------+
> >> | | ecf6709d07 | 2580d6b795 |
> >> +------------------------------------------------------------------+------------+------------+
> >> | boot_successes | 0 | 0 |
> >> | boot_failures | 8 | 8 |
> >> | invoked_oom-killer:gfp_mask=0x | 8 | |
> >> | Mem-Info | 8 | |
> >> | Kernel_panic-not_syncing:Out_of_memory_and_no_killable_processes | 8 | |
> >> | BUG:kernel_reboot-without-warning_in_boot_stage | 0 | 8 |
> >> +------------------------------------------------------------------+------------+------------+
> >
> >What does this mean?
>
> It means BUG:BUG:kernel_reboot-without-warning_in_boot_stage occurred 8 times
> in boot tests for commit 2580d6b795, while 0 time for its parent ecf6709d07.
I don't have a commit 2580d6b795.
The commit with the title "init, tracing: Have printk come through the
trace events for initcall_debug" is 4e37958d1288ce. linux-next doesn't
have that commit sha1 either.
>
> >
> >>
> >>
> >>
> >> [ 0.000000] RAMDISK: [mem 0x1b7e2000-0x1ffcffff]
> >> [ 0.000000] ACPI: Early table checksum verification disabled
> >> [ 0.000000] ACPI: RSDP 0x00000000000F6860 000014 (v00 BOCHS )
> >> [ 0.000000] ACPI: RSDT 0x000000001FFE1628 000030 (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001)
> >> [ 0.000000] ACPI: FACP 0x000000001FFE147C 000074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001)
> >> BUG: kernel reboot-without-warning in boot stage
> >>
> >> Elapsed time: 10
> >>
> >> #!/bin/bash
> >>
> >>
> >>
> >> To reproduce:
> >>
> >> git clone https://github.com/intel/lkp-tests.git
> >> cd lkp-tests
> >> bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
> >>
> >
> >The config boots fine for me. But I don't have the setup to run the
> >above and get it to work, nor the time to figure out why it doesn't
> >work.
>
> Could you paste your failure log here, we can see if there is something we can help.
I tried it on a more up-to-date box, after checking out my commit with
the title you say is an error. I compiled your config with gcc (GCC)
7.3.1 20180130 (Red Hat 7.3.1-2), and ran the above (which did work).
It ended after it got to a login prompt.
---
[..]
[ 10.588029] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[ 10.589363] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
[ 10.590385] cfg80211: failed to load regulatory.db
[ 10.610002] Freeing unused kernel memory: 1980K
[ 10.610533] Write protecting the kernel read-only data: 49152k
[ 10.615728] Freeing unused kernel memory: 2028K
[ 10.620754] Freeing unused kernel memory: 464K
INIT: version 2.88 booting
/etc/rcS.d/S00fbsetup: line 3: /sbin/modprobe: not found
Please wait: booting...
[ 10.676861] rc (151) used greatest stack depth: 27848 bytes left
Starting udev
[ 10.750281] udevd[175]: starting version 3.1.5
[ 10.759923] udevd (175) used greatest stack depth: 27696 bytes left
[ 11.129999] udevadm (178) used greatest stack depth: 26696 bytes left
Populating dev cache
INIT: Entering runlevel: 5
Configuring network interfaces... done.
Starting syslogd/klogd: done
Poky (Yocto Project Reference Distro) 2.1 qemux86-64 /dev/ttyS0
qemux86-64 login:
---
What am I suppose to see?
-- Steve
On 04/09, Steven Rostedt wrote:
>On Tue, 10 Apr 2018 09:23:40 +0800
>Ye Xiaolong <[email protected]> wrote:
>
>> Hi, Steven
>>
>> On 04/09, Steven Rostedt wrote:
>> >On Mon, 9 Apr 2018 13:32:52 +0800
>> >kernel test robot <[email protected]> wrote:
>> >
>> >> FYI, we noticed the following commit (built with gcc-7):
>> >>
>> >> commit: 2580d6b795e25879c825a0891cf67390f665b11f ("init, tracing: Have printk come through the trace events for initcall_debug")
>> >> url: https://github.com/0day-ci/linux/commits/Steven-Rostedt/init-tracing/20180407-130743
>> >>
>> >>
>> >> in testcase: boot
>> >>
>> >> on test machine: qemu-system-x86_64 -enable-kvm -cpu Nehalem -smp 2 -m 512M
>> >>
>> >> caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
>> >>
>> >>
>> >> +------------------------------------------------------------------+------------+------------+
>> >> | | ecf6709d07 | 2580d6b795 |
>> >> +------------------------------------------------------------------+------------+------------+
>> >> | boot_successes | 0 | 0 |
>> >> | boot_failures | 8 | 8 |
>> >> | invoked_oom-killer:gfp_mask=0x | 8 | |
>> >> | Mem-Info | 8 | |
>> >> | Kernel_panic-not_syncing:Out_of_memory_and_no_killable_processes | 8 | |
>> >> | BUG:kernel_reboot-without-warning_in_boot_stage | 0 | 8 |
>> >> +------------------------------------------------------------------+------------+------------+
>> >
>> >What does this mean?
>>
>> It means BUG:BUG:kernel_reboot-without-warning_in_boot_stage occurred 8 times
>> in boot tests for commit 2580d6b795, while 0 time for its parent ecf6709d07.
>
>I don't have a commit 2580d6b795.
>
>The commit with the title "init, tracing: Have printk come through the
>trace events for initcall_debug" is 4e37958d1288ce. linux-next doesn't
>have that commit sha1 either.
This commit was generated by 0day service, it captured your email patchset which posted
on LKML and then applied it on top of 06dd3dfeea60 and performed build/boot tests accordingly.
>
>
>>
>> >
>> >>
>> >>
>> >>
>> >> [ 0.000000] RAMDISK: [mem 0x1b7e2000-0x1ffcffff]
>> >> [ 0.000000] ACPI: Early table checksum verification disabled
>> >> [ 0.000000] ACPI: RSDP 0x00000000000F6860 000014 (v00 BOCHS )
>> >> [ 0.000000] ACPI: RSDT 0x000000001FFE1628 000030 (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001)
>> >> [ 0.000000] ACPI: FACP 0x000000001FFE147C 000074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001)
>> >> BUG: kernel reboot-without-warning in boot stage
>> >>
>> >> Elapsed time: 10
>> >>
>> >> #!/bin/bash
>> >>
>> >>
>> >>
>> >> To reproduce:
>> >>
>> >> git clone https://github.com/intel/lkp-tests.git
>> >> cd lkp-tests
>> >> bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
>> >>
>> >
>> >The config boots fine for me. But I don't have the setup to run the
>> >above and get it to work, nor the time to figure out why it doesn't
>> >work.
>>
>> Could you paste your failure log here, we can see if there is something we can help.
>
>I tried it on a more up-to-date box, after checking out my commit with
>the title you say is an error. I compiled your config with gcc (GCC)
>7.3.1 20180130 (Red Hat 7.3.1-2), and ran the above (which did work).
>It ended after it got to a login prompt.
>
>---
>[..]
>[ 10.588029] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
>[ 10.589363] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
>[ 10.590385] cfg80211: failed to load regulatory.db
>[ 10.610002] Freeing unused kernel memory: 1980K
>[ 10.610533] Write protecting the kernel read-only data: 49152k
>[ 10.615728] Freeing unused kernel memory: 2028K
>[ 10.620754] Freeing unused kernel memory: 464K
>INIT: version 2.88 booting
>/etc/rcS.d/S00fbsetup: line 3: /sbin/modprobe: not found
>
>Please wait: booting...
>[ 10.676861] rc (151) used greatest stack depth: 27848 bytes left
>Starting udev
>[ 10.750281] udevd[175]: starting version 3.1.5
>[ 10.759923] udevd (175) used greatest stack depth: 27696 bytes left
>[ 11.129999] udevadm (178) used greatest stack depth: 26696 bytes left
>Populating dev cache
>INIT: Entering runlevel: 5
>Configuring network interfaces... done.
>Starting syslogd/klogd: done
>
>Poky (Yocto Project Reference Distro) 2.1 qemux86-64 /dev/ttyS0
>
>qemux86-64 login:
>---
>
>What am I suppose to see?
>
So I figure the gap may be 0day bot applied your patchset to a inappropriate base.
Thanks,
Xiaolong
>-- Steve
>