how to collect information regarding function calls in run time?

how to collect information regarding function calls in run time?

[Pedro Terra Delboni]

Hello!

I have a question about profiling, please, let me know if this is not
the right mailing list to post these kind of questions.

Is there a way for me to record how many times each specific direct
call to a function happened?
I've seen ways of profiling the kernel that calculate how much time
the system spent in each function, but having a bit more information
related to calls would be really good.

I would like to know, for every function call that happens in run
time, who called it (it's for a project in my University).

I've also seen (I may be mistaken here) that by compiling the kernel
with perf, each function will start with a stub call which can be used
for profiling purposes.
I was thinking in using this stub to plug a function to dump
(somewhere) the return address before it's own (so I can collect the
info about where the call came from).
I wonder if changing every stub calls in all functions to dump its
return address wouldn't create too much of a latency impact to the
point of skewing the control flow of the execution,
or even making it nonviable.

Thanks in advance, any help would be great!
If this is not the right place to post this question, I would
appreciate if anyone could point me to the right place.

Thanks
Pedro

_______________________________________________
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

Re: how to collect information regarding function calls in run time?

[Bharath Vedartham]

On Wed, Apr 03, 2019 at 04:25:02PM -0300, Pedro Terra Delboni wrote:
> Hello!
> 
> I have a question about profiling, please, let me know if this is not
> the right mailing list to post these kind of questions.
>
> Is there a way for me to record how many times each specific direct
> call to a function happened?
> I've seen ways of profiling the kernel that calculate how much time
> the system spent in each function, but having a bit more information
> related to calls would be really good.
> 
> I would like to know, for every function call that happens in run
> time, who called it (it's for a project in my University).
> 
> I've also seen (I may be mistaken here) that by compiling the kernel
> with perf, each function will start with a stub call which can be used
> for profiling purposes.
> I was thinking in using this stub to plug a function to dump
> (somewhere) the return address before it's own (so I can collect the
> info about where the call came from).
> I wonder if changing every stub calls in all functions to dump its
> return address wouldn't create too much of a latency impact to the
> point of skewing the control flow of the execution,
> or even making it nonviable.
> 
> Thanks in advance, any help would be great!
> If this is not the right place to post this question, I would
> appreciate if anyone could point me to the right place.
> 
> Thanks
> Pedro
>
I am assuming your talking about profiling functions in the linux kernel.
You can the kernel tracing infrastructure called kprobes to record how
many times a function is called by a particular process or for a time
interval. Kprobes will dynamically put a 'tracepoint'(if you use
debuggers it is similar to 'breakpoints') at the function call. 
You can then trace that particular function to see how many times its called and stuff like that. 
Luckily perf comes with kprobes! yay!
eg:
	perf probe --add <function_name> 
This will add a probe to the function. You can then trace it by:
	perf record -e <function_name> <options>

The perf.data file will give you all the info you need. 
Also for better output from perf, enable CONFIG_FRAME_POINTER in your
kernel build(assuming it is a custom build).
Check this out for more info:
     http://www.brendangregg.com/perf.html
There is similar functionality in user space. It is called uprobes(user
probes) similar to kprobes(kernel probes).

Now before you click on the above link, use kprobes only for functions
which do not have a static tracepoint. Certain interesting functions like system
calls, scheduler specific functions, mm functions like kmalloc etc. You
can find the static tracepoints in /sys/kernel/debug/tracing/events. You
do not need kprobes. For example if your tracing the write system call,
you can just do:
	perf record -e syscalls:sys_enter_write -ag 1 (For system wide
	tracing.)

Again check out the above link for more info!

Hope I was helpful!


> _______________________________________________
> Kernelnewbies mailing list
> Kernelnewbies@kernelnewbies.org
> https://lists.kerne
lnewbies.org/mailman/listinfo/kernelnewbies

_______________________________________________
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

Re: how to collect information regarding function calls in run time?

[Pedro Terra Delboni]

[-- Attachment #1.1: Type: text/plain, Size: 3373 bytes --]

Sorry to revive this old thread, and thank you for the suggestions given,
but I've been trying to make these work for my case with little success and
I need a hand to understand what I'm doing wrong.

Regarding bpftrace: This seemed like the best option since I could use it
to count frames of the stack with depth 2, allowing me to know precisely
the amount of times each specific call has been made. However, I could not
use it because since I have to probe every function, it would raise an
error related to open file limit. I've tried setting the open file limit to
unlimited, but the command I used to do so said it was impossible, also the
current limit is set to 1048576, so I'm guessing that probing every
function isn't a viable solution.

Regarding perf: I couldn't find out how to count each call with perf, but I
could count how many times each function was called. Differently from
bpftrace, I need to use a command for each function I would like to probe,
so I created a script that would get all the functions that can be probed
and call that command for each of them. Unfortunately this took too long,
so I stopped after a certain number of probes were created and executed my
test, at that time, the machine hanged.
With a low number of functions being probed it worked fine though.

Right now, the solution I can see is using bpftrace to probe a very limited
number of calls, profile an execution, then repeat the profile for
different set of probes, which can take a very long time.
Is there an easier way (less time consuming) to achieve the same results
(counting how many times each call instruction has been executed)?

Thanks you for the attention,
Pedro

On Wed, Apr 3, 2019 at 6:23 PM Augusto Mecking Caringi <
augustocaringi@gmail.com> wrote:

> Hi,
>
> On Wed, Apr 3, 2019 at 9:26 PM Pedro Terra Delboni <terra0009@gmail.com>
> wrote:
> >
> > Hello!
> >
> > I have a question about profiling, please, let me know if this is not
> > the right mailing list to post these kind of questions.
> >
> > Is there a way for me to record how many times each specific direct
> > call to a function happened?
> > I've seen ways of profiling the kernel that calculate how much time
> > the system spent in each function, but having a bit more information
> > related to calls would be really good.
> >
> > I would like to know, for every function call that happens in run
> > time, who called it (it's for a project in my University).
> >
> > I've also seen (I may be mistaken here) that by compiling the kernel
> > with perf, each function will start with a stub call which can be used
> > for profiling purposes.
> > I was thinking in using this stub to plug a function to dump
> > (somewhere) the return address before it's own (so I can collect the
> > info about where the call came from).
> > I wonder if changing every stub calls in all functions to dump its
> > return address wouldn't create too much of a latency impact to the
> > point of skewing the control flow of the execution,
> > or even making it nonviable.
> >
> > Thanks in advance, any help would be great!
> > If this is not the right place to post this question, I would
> > appreciate if anyone could point me to the right place.
>
> There is also a new tool called bpftrace that can help you...
>
> https://github.com/iovisor/bpftrace
>
> Regards,
>
> --
> Augusto Mecking Caringi
>

[-- Attachment #1.2: Type: text/html, Size: 4267 bytes --]

[-- Attachment #2: Type: text/plain, Size: 170 bytes --]

_______________________________________________
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

Re: how to collect information regarding function calls in run time?

[Greg KH]

On Tue, May 14, 2019 at 10:55:40AM -0300, Pedro Terra Delboni wrote:
> Sorry to revive this old thread, and thank you for the suggestions given,
> but I've been trying to make these work for my case with little success and
> I need a hand to understand what I'm doing wrong.

Given that this is a university assignment, asking for help from random
people on the internet seems like an odd request, do we too get a grade
for this?  :)

Good luck!

greg k-h

_______________________________________________
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

Re: how to collect information regarding function calls in run time?

[Pedro Terra Delboni]

[-- Attachment #1.1: Type: text/plain, Size: 837 bytes --]

Sorry, I believe I was not clear in how this relates to my university.
I'm a post-graduate student working on a thesis, I'm not looking for the
answer of an exercise proposed by the university.
So neither you nor I can get a grade from this (though this may help me
finish things sooner).

On Tue, May 14, 2019 at 11:05 AM Greg KH <greg@kroah.com> wrote:

> On Tue, May 14, 2019 at 10:55:40AM -0300, Pedro Terra Delboni wrote:
> > Sorry to revive this old thread, and thank you for the suggestions given,
> > but I've been trying to make these work for my case with little success
> and
> > I need a hand to understand what I'm doing wrong.
>
> Given that this is a university assignment, asking for help from random
> people on the internet seems like an odd request, do we too get a grade
> for this?  :)
>
> Good luck!
>
> greg k-h
>

[-- Attachment #1.2: Type: text/html, Size: 1211 bytes --]

[-- Attachment #2: Type: text/plain, Size: 170 bytes --]

_______________________________________________
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

Re: how to collect information regarding function calls in run time?

[Valdis Klētnieks]

[-- Attachment #1.1: Type: text/plain, Size: 2377 bytes --]

On Tue, 14 May 2019 10:55:40 -0300, Pedro Terra Delboni said:

> Regarding bpftrace: This seemed like the best option since I could use it
> to count frames of the stack with depth 2, allowing me to know precisely
> the amount of times each specific call has been made. However, I could not
> use it because since I have to probe every function, it would raise an
> error related to open file limit. I've tried setting the open file limit to
> unlimited, but the command I used to do so said it was impossible, also the
> current limit is set to 1048576, so I'm guessing that probing every
> function isn't a viable solution.

What problem are you trying to solve?

If you're trying to count how often *every* function is called, and the fact
that one way to do it has an upper limit of a million is a problem, chances are
that you haven't figured out what the *question* is yet.

Usually, the number of calls isn't that important, the total runtime spent in
the function is important.  A one-liner inline accessor function that compiles
down to 2-3 machine opcodes can be called tens of thousands of times a second
and not be noticed.  A function that takes milliseconds to complete will be
noticed if it's called only a few dozen times a second.

If you're trying to figure out how the functions fit together, a static call
graph analysis tool to produce a map of what calls what may be what you need.

Having said that, a kernel built with gcov or ftrace support will give you the
info you need.

See kernel/gcove/Kconfig and http://heim.ifi.uio.no/~knuto/kernel/4.14/dev-tools/gcov.html
if you want to go that route.

Resources for ftrace call counts:

http://www.brendangregg.com/blog/2014-07-13/linux-ftrace-function-counting.html

https://wiki.linaro.org/KenWerner/Sandbox/ftrace and see section 'function profiler'.

Be prepared for your kernel to be quite slow, and have to do a *lot* of data
reduction.

Note that you'll probably need to run for at least several hours, and of course
the function counts will be *very* dependent on what you do - what gets called
while I'm doing stuff like writing e-mail is very different from what happens
during a kernel compile, and both of those are different from the function
counts that happen when I back up my laptop to an external USB disk.

(Note I've not *tried* any of the above - this laptop is slow enough as it is :)

[-- Attachment #1.2: Type: application/pgp-signature, Size: 832 bytes --]

[-- Attachment #2: Type: text/plain, Size: 170 bytes --]

_______________________________________________
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

Re: how to collect information regarding function calls in run time?

[Pedro Terra Delboni]

On Tue, May 14, 2019 at 2:46 PM Valdis Klētnieks
<valdis.kletnieks@vt.edu> wrote:
>
> On Tue, 14 May 2019 10:55:40 -0300, Pedro Terra Delboni said:
>
> > Regarding bpftrace: This seemed like the best option since I could use it
> > to count frames of the stack with depth 2, allowing me to know precisely
> > the amount of times each specific call has been made. However, I could not
> > use it because since I have to probe every function, it would raise an
> > error related to open file limit. I've tried setting the open file limit to
> > unlimited, but the command I used to do so said it was impossible, also the
> > current limit is set to 1048576, so I'm guessing that probing every
> > function isn't a viable solution.
>
> What problem are you trying to solve?
>
> If you're trying to count how often *every* function is called, and the fact
> that one way to do it has an upper limit of a million is a problem, chances are
> that you haven't figured out what the *question* is yet.
>
> Usually, the number of calls isn't that important, the total runtime spent in
> the function is important.  A one-liner inline accessor function that compiles
> down to 2-3 machine opcodes can be called tens of thousands of times a second
> and not be noticed.  A function that takes milliseconds to complete will be
> noticed if it's called only a few dozen times a second.
>
> If you're trying to figure out how the functions fit together, a static call
> graph analysis tool to produce a map of what calls what may be what you need.
>
> Having said that, a kernel built with gcov or ftrace support will give you the
> info you need.
>
> See kernel/gcove/Kconfig and http://heim.ifi.uio.no/~knuto/kernel/4.14/dev-tools/gcov.html
> if you want to go that route.
>
> Resources for ftrace call counts:
>
> http://www.brendangregg.com/blog/2014-07-13/linux-ftrace-function-counting.html
>
> https://wiki.linaro.org/KenWerner/Sandbox/ftrace and see section 'function profiler'.
>
> Be prepared for your kernel to be quite slow, and have to do a *lot* of data
> reduction.
>
> Note that you'll probably need to run for at least several hours, and of course
> the function counts will be *very* dependent on what you do - what gets called
> while I'm doing stuff like writing e-mail is very different from what happens
> during a kernel compile, and both of those are different from the function
> counts that happen when I back up my laptop to an external USB disk.
>
> (Note I've not *tried* any of the above - this laptop is slow enough as it is :)


Thank you for the answer, I'll follow the appointed links.

I agree that the question alone seems like a weird one, I just assumed
when I wrote my first email that the explaining the motivation would
only consume time of the reader.

The subject I'm working on is Control-Flow Integrity, which instrument
a code so that each indirect jump (which are usually returns or
indirect calls) verify if the address they are returning is a valid
one (so there is a code stub that runs in every function call and
return).
One tool was implemented by one of the university researchers in order
to add such instrumentation to the kernel Linux [1].

[1] https://www.blackhat.com/docs/asia-17/materials/asia-17-Moreira-Drop-The-Rop-Fine-Grained-Control-Flow-Integrity-For-The-Linux-Kernel.pdf

A more "secure" version of this implementation was proven to increase
the latency by quite a lot, thus it isn't a viable solution atm. The
latency increase is done mostly by the instrumentation when the
function returns.
The reason I want to count call instructions execution is because the
function return tied to the most executed call instruction will be the
one that will cause the greater increase in execution time, so by
inlining that call we'll be exchanging this cost for the cache impact
of the code expansion (as the code stub won't exist anymore for this
call).
The objective is to try to measure in which cases this exchange is a
viable one (so we can decide which functions to inline/expand), and
also try to find how many expansions would be necessary in order to
increase viability of the current solution.
I understand that the profiling result will change based on execution.
We don't assume that the profiling will solve the latency issue for
every case, but if it does for the profiled case it would already be
an interesting result.

This is only researching for now, I hope the results would be
interesting to the community in the future, so any help would be
appreciated. Please, let me know if I wasn't clear, or if you have any
other ideas.

Thanks a lot

_______________________________________________
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

Re: how to collect information regarding function calls in run time?

[Valdis Klētnieks]

[-- Attachment #1.1: Type: text/plain, Size: 1963 bytes --]

On Tue, 14 May 2019 16:11:51 -0300, Pedro Terra Delboni said:

> I agree that the question alone seems like a weird one, I just assumed
> when I wrote my first email that the explaining the motivation would
> only consume time of the reader.

Asking "what problem are you trying to solve" is a standard question, because
whenever a programmer is saying "I can't get X to do Y", a good 85% of the time
it turns out that  isn't working because using W to do Z is the
already-existing API for what they actually wanted to do....

> The subject I'm working on is Control-Flow Integrity, which instrument
> a code so that each indirect jump (which are usually returns or
> indirect calls) verify if the address they are returning is a valid
> one (so there is a code stub that runs in every function call and
> return).

> The reason I want to count call instructions execution is because the
> function return tied to the most executed call instruction will be the
> one that will cause the greater increase in execution time, so by
> inlining that call we'll be exchanging this cost for the cache impact
> of the code expansion (as the code stub won't exist anymore for this
> call).

I suspect that the vast majority of functions that are *that* heavily used are
either (a) already inlined or (b) too large to inline - for instance, kmalloc
is used heavily, but having separate inlined copies everyplace to avoid the
return statement is going to bloat the code - and even worse, make almost all
the inline copies cache-cold instead of one shared cache-hot chunk of 2K.

And the question we *should* be asking is *not* "is the return address a plausible
one".  It's "is the return address *the one we were called from*".  Checking
whether kmalloc is about to return to a valid call point doesn't tell you much.
Finding out that kmalloc is about to return to one of the 193,358 *other* call
points rather than the one it was actually called from is something big.




[-- Attachment #1.2: Type: application/pgp-signature, Size: 832 bytes --]

[-- Attachment #2: Type: text/plain, Size: 170 bytes --]

_______________________________________________
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

Re: how to collect information regarding function calls in run time?

[Pedro Terra Delboni]

On Fri, May 17, 2019 at 11:09 AM Valdis Klētnieks
<valdis.kletnieks@vt.edu> wrote:
>
> On Tue, 14 May 2019 16:11:51 -0300, Pedro Terra Delboni said:
>
> > I agree that the question alone seems like a weird one, I just assumed
> > when I wrote my first email that the explaining the motivation would
> > only consume time of the reader.
>
> Asking "what problem are you trying to solve" is a standard question, because
> whenever a programmer is saying "I can't get X to do Y", a good 85% of the time
> it turns out that  isn't working because using W to do Z is the
> already-existing API for what they actually wanted to do....
>
> > The subject I'm working on is Control-Flow Integrity, which instrument
> > a code so that each indirect jump (which are usually returns or
> > indirect calls) verify if the address they are returning is a valid
> > one (so there is a code stub that runs in every function call and
> > return).
>
> > The reason I want to count call instructions execution is because the
> > function return tied to the most executed call instruction will be the
> > one that will cause the greater increase in execution time, so by
> > inlining that call we'll be exchanging this cost for the cache impact
> > of the code expansion (as the code stub won't exist anymore for this
> > call).
>
> I suspect that the vast majority of functions that are *that* heavily used are
> either (a) already inlined or (b) too large to inline - for instance, kmalloc
> is used heavily, but having separate inlined copies everyplace to avoid the
> return statement is going to bloat the code - and even worse, make almost all
> the inline copies cache-cold instead of one shared cache-hot chunk of 2K.

It will bloat the code and the copies will negatively impact the
cache, however, the current implementation is very time consuming, to
the point where we believe the cache impact is a plausible option.

>
> And the question we *should* be asking is *not* "is the return address a plausible
> one".  It's "is the return address *the one we were called from*".  Checking
> whether kmalloc is about to return to a valid call point doesn't tell you much.
> Finding out that kmalloc is about to return to one of the 193,358 *other* call
> points rather than the one it was actually called from is something big.
>

The reason we relaxed the question from which address we were called
to which address is plausible is because verifying the address which
we were called is a lot harder than verifying if we are returning to a
kmalloc call (whichever it may be).
The implementation which just verify a plausible address added enough
latency for us to believe it is a viable option.
The more secure implementation which verifies if a call is returning
to its exact call point is the one we are trying to find ways to make
it viable.

>
>

_______________________________________________
Kernelnewbies mailing list
Kernelnewbies@kernelnewbies.org
https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies