2021-05-10 15:26:11

by Shivank Garg

[permalink] [raw]
Subject: Profiling execution time for __alloc_pages_nodemask

Hi Everyone!

I want to profile the time taken to execute the __alloc_pages_nodemask
for different linux configurations/parameters.
To measure the execution time, I use the ktime_get() apis. I get the
ktime_get() on the top, and I want to do ktime_sub(ktime_get(),ktime)
and record it in a tracepoint.
However, the patch on implementation prevents the kernel from booting
up. I debugged the bug to find out that the issue recurs on adding
ktime_get() inside the __alloc_pages_nodemask path. So, that the
kernel fails to boot up ( and show the blank screen without any logs )
I'm using the Linux kernel 5.6.13 (5821a5593fa9f28eb6fcc95c35d00454d9bb8624)

Is it an expected behavior? or a BUG? Has anyone else faced the same issue?

Can you please suggest, what would be a good way to measure execution
time for page allocation (if not ktime_get)

Stay Safe!
Best Regards,
Shivank Garg
Open-Source Enthusiast and Student, IIT Kanpur


2021-05-11 00:01:56

by Yang Shi

[permalink] [raw]
Subject: Re: Profiling execution time for __alloc_pages_nodemask

On Mon, May 10, 2021 at 7:57 AM Shivank Garg <[email protected]> wrote:
>
> Hi Everyone!
>
> I want to profile the time taken to execute the __alloc_pages_nodemask
> for different linux configurations/parameters.
> To measure the execution time, I use the ktime_get() apis. I get the
> ktime_get() on the top, and I want to do ktime_sub(ktime_get(),ktime)
> and record it in a tracepoint.
> However, the patch on implementation prevents the kernel from booting
> up. I debugged the bug to find out that the issue recurs on adding
> ktime_get() inside the __alloc_pages_nodemask path. So, that the
> kernel fails to boot up ( and show the blank screen without any logs )
> I'm using the Linux kernel 5.6.13 (5821a5593fa9f28eb6fcc95c35d00454d9bb8624)

Is there any reason that prevents you from using some advanced tools,
i.e. perf, bcc/bpftrace, etc? They are much simpler than adding
instrumentation in kernel.

>
> Is it an expected behavior? or a BUG? Has anyone else faced the same issue?
>
> Can you please suggest, what would be a good way to measure execution
> time for page allocation (if not ktime_get)
>
> Stay Safe!
> Best Regards,
> Shivank Garg
> Open-Source Enthusiast and Student, IIT Kanpur
>

2021-05-11 05:33:09

by Shivank Garg

[permalink] [raw]
Subject: Re: Profiling execution time for __alloc_pages_nodemask

>Are you maybe calling ktime_get() too early during boot, where some
>subsystems are just about to be brought up?

Thanks David, I guess this is the issue.

>Is there any reason that prevents you from using some advanced tools,
>i.e. perf, bcc/bpftrace, etc? They are much simpler than adding
>instrumentation in kernel.

Actually, I want to record the arguments for the memory allocator and
filter out the calls I don't need (which are creating noise).
For instance, I'm only interested in particular order and flags.

This is the reason I added my custom tracepoint, which theoretically
looked easy to implement without adding much overhead.

Thanks,
Shivank

On Tue, May 11, 2021 at 5:30 AM Yang Shi <[email protected]> wrote:
>
> On Mon, May 10, 2021 at 7:57 AM Shivank Garg <[email protected]> wrote:
> >
> > Hi Everyone!
> >
> > I want to profile the time taken to execute the __alloc_pages_nodemask
> > for different linux configurations/parameters.
> > To measure the execution time, I use the ktime_get() apis. I get the
> > ktime_get() on the top, and I want to do ktime_sub(ktime_get(),ktime)
> > and record it in a tracepoint.
> > However, the patch on implementation prevents the kernel from booting
> > up. I debugged the bug to find out that the issue recurs on adding
> > ktime_get() inside the __alloc_pages_nodemask path. So, that the
> > kernel fails to boot up ( and show the blank screen without any logs )
> > I'm using the Linux kernel 5.6.13 (5821a5593fa9f28eb6fcc95c35d00454d9bb8624)
>
> Is there any reason that prevents you from using some advanced tools,
> i.e. perf, bcc/bpftrace, etc? They are much simpler than adding
> instrumentation in kernel.
>
> >
> > Is it an expected behavior? or a BUG? Has anyone else faced the same issue?
> >
> > Can you please suggest, what would be a good way to measure execution
> > time for page allocation (if not ktime_get)
> >
> > Stay Safe!
> > Best Regards,
> > Shivank Garg
> > Open-Source Enthusiast and Student, IIT Kanpur
> >

2021-05-12 03:58:10

by Yang Shi

[permalink] [raw]
Subject: Re: Profiling execution time for __alloc_pages_nodemask

On Mon, May 10, 2021 at 10:31 PM Shivank Garg <[email protected]> wrote:
>
> >Are you maybe calling ktime_get() too early during boot, where some
> >subsystems are just about to be brought up?
>
> Thanks David, I guess this is the issue.
>
> >Is there any reason that prevents you from using some advanced tools,
> >i.e. perf, bcc/bpftrace, etc? They are much simpler than adding
> >instrumentation in kernel.
>
> Actually, I want to record the arguments for the memory allocator and
> filter out the calls I don't need (which are creating noise).
> For instance, I'm only interested in particular order and flags.

BPF can do so too. You can either attach to kprobe or tracepoint, then
filter out the calls by the function's parameters or tracepoint's
fields.

>
> This is the reason I added my custom tracepoint, which theoretically
> looked easy to implement without adding much overhead.
>
> Thanks,
> Shivank
>
> On Tue, May 11, 2021 at 5:30 AM Yang Shi <[email protected]> wrote:
> >
> > On Mon, May 10, 2021 at 7:57 AM Shivank Garg <[email protected]> wrote:
> > >
> > > Hi Everyone!
> > >
> > > I want to profile the time taken to execute the __alloc_pages_nodemask
> > > for different linux configurations/parameters.
> > > To measure the execution time, I use the ktime_get() apis. I get the
> > > ktime_get() on the top, and I want to do ktime_sub(ktime_get(),ktime)
> > > and record it in a tracepoint.
> > > However, the patch on implementation prevents the kernel from booting
> > > up. I debugged the bug to find out that the issue recurs on adding
> > > ktime_get() inside the __alloc_pages_nodemask path. So, that the
> > > kernel fails to boot up ( and show the blank screen without any logs )
> > > I'm using the Linux kernel 5.6.13 (5821a5593fa9f28eb6fcc95c35d00454d9bb8624)
> >
> > Is there any reason that prevents you from using some advanced tools,
> > i.e. perf, bcc/bpftrace, etc? They are much simpler than adding
> > instrumentation in kernel.
> >
> > >
> > > Is it an expected behavior? or a BUG? Has anyone else faced the same issue?
> > >
> > > Can you please suggest, what would be a good way to measure execution
> > > time for page allocation (if not ktime_get)
> > >
> > > Stay Safe!
> > > Best Regards,
> > > Shivank Garg
> > > Open-Source Enthusiast and Student, IIT Kanpur
> > >

2021-05-12 19:38:13

by Shivank Garg

[permalink] [raw]
Subject: Re: Profiling execution time for __alloc_pages_nodemask

>> Actually, I want to record the arguments for the memory allocator and
>> filter out the calls I don't need (which are creating noise).
>> For instance, I'm only interested in particular order and flags.

>BPF can do so too. You can either attach to kprobe or tracepoint, then
>filter out the calls by the function's parameters or tracepoint's
>fields.

Thanks Yang for the suggestion, I'll try the BPF. Anyway my problem
was solved by the filter in custom tracepoints (for instance,
tracing/events/kmem/filter).

Also, I used trace_*_enabled() to first check if tracepoint is enabled
and take ktime_get() only after that. This solved my initial issue.

Thanks David, Yang and the Linux community for helping me identify my
issue and solve it.

Best Regards,
Shivank