* how to collect information regarding function calls in run time? @ 2019-04-03 19:25 Pedro Terra Delboni 2019-04-03 20:15 ` Bharath Vedartham [not found] ` <CADFy_4FJODA9gT7Enb+eLt-bdJBkkgTmqhhb3AhJhjibgbzD2A@mail.gmail.com> 0 siblings, 2 replies; 9+ messages in thread From: Pedro Terra Delboni @ 2019-04-03 19:25 UTC (permalink / raw) To: kernelnewbies 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: how to collect information regarding function calls in run time? 2019-04-03 19:25 how to collect information regarding function calls in run time? Pedro Terra Delboni @ 2019-04-03 20:15 ` Bharath Vedartham [not found] ` <CADFy_4FJODA9gT7Enb+eLt-bdJBkkgTmqhhb3AhJhjibgbzD2A@mail.gmail.com> 1 sibling, 0 replies; 9+ messages in thread From: Bharath Vedartham @ 2019-04-03 20:15 UTC (permalink / raw) To: Pedro Terra Delboni; +Cc: kernelnewbies 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
[parent not found: <CADFy_4FJODA9gT7Enb+eLt-bdJBkkgTmqhhb3AhJhjibgbzD2A@mail.gmail.com>]
* Re: how to collect information regarding function calls in run time? [not found] ` <CADFy_4FJODA9gT7Enb+eLt-bdJBkkgTmqhhb3AhJhjibgbzD2A@mail.gmail.com> @ 2019-05-14 13:55 ` Pedro Terra Delboni 2019-05-14 14:05 ` Greg KH 2019-05-14 17:45 ` Valdis Klētnieks 0 siblings, 2 replies; 9+ messages in thread From: Pedro Terra Delboni @ 2019-05-14 13:55 UTC (permalink / raw) To: kernelnewbies [-- 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: how to collect information regarding function calls in run time? 2019-05-14 13:55 ` Pedro Terra Delboni @ 2019-05-14 14:05 ` Greg KH 2019-05-14 14:14 ` Pedro Terra Delboni 2019-05-14 17:45 ` Valdis Klētnieks 1 sibling, 1 reply; 9+ messages in thread From: Greg KH @ 2019-05-14 14:05 UTC (permalink / raw) To: Pedro Terra Delboni; +Cc: kernelnewbies 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: how to collect information regarding function calls in run time? 2019-05-14 14:05 ` Greg KH @ 2019-05-14 14:14 ` Pedro Terra Delboni 0 siblings, 0 replies; 9+ messages in thread From: Pedro Terra Delboni @ 2019-05-14 14:14 UTC (permalink / raw) To: Greg KH; +Cc: kernelnewbies [-- 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: how to collect information regarding function calls in run time? 2019-05-14 13:55 ` Pedro Terra Delboni 2019-05-14 14:05 ` Greg KH @ 2019-05-14 17:45 ` Valdis Klētnieks 2019-05-14 19:11 ` Pedro Terra Delboni 1 sibling, 1 reply; 9+ messages in thread From: Valdis Klētnieks @ 2019-05-14 17:45 UTC (permalink / raw) To: Pedro Terra Delboni; +Cc: kernelnewbies [-- 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: how to collect information regarding function calls in run time? 2019-05-14 17:45 ` Valdis Klētnieks @ 2019-05-14 19:11 ` Pedro Terra Delboni 2019-05-17 14:09 ` Valdis Klētnieks 0 siblings, 1 reply; 9+ messages in thread From: Pedro Terra Delboni @ 2019-05-14 19:11 UTC (permalink / raw) To: Valdis Klētnieks; +Cc: kernelnewbies 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: how to collect information regarding function calls in run time? 2019-05-14 19:11 ` Pedro Terra Delboni @ 2019-05-17 14:09 ` Valdis Klētnieks 2019-05-17 16:19 ` Pedro Terra Delboni 0 siblings, 1 reply; 9+ messages in thread From: Valdis Klētnieks @ 2019-05-17 14:09 UTC (permalink / raw) To: Pedro Terra Delboni; +Cc: kernelnewbies [-- 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: how to collect information regarding function calls in run time? 2019-05-17 14:09 ` Valdis Klētnieks @ 2019-05-17 16:19 ` Pedro Terra Delboni 0 siblings, 0 replies; 9+ messages in thread From: Pedro Terra Delboni @ 2019-05-17 16:19 UTC (permalink / raw) To: Valdis Klētnieks; +Cc: kernelnewbies 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
end of thread, other threads:[~2019-05-17 16:19 UTC | newest] Thread overview: 9+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2019-04-03 19:25 how to collect information regarding function calls in run time? Pedro Terra Delboni 2019-04-03 20:15 ` Bharath Vedartham [not found] ` <CADFy_4FJODA9gT7Enb+eLt-bdJBkkgTmqhhb3AhJhjibgbzD2A@mail.gmail.com> 2019-05-14 13:55 ` Pedro Terra Delboni 2019-05-14 14:05 ` Greg KH 2019-05-14 14:14 ` Pedro Terra Delboni 2019-05-14 17:45 ` Valdis Klētnieks 2019-05-14 19:11 ` Pedro Terra Delboni 2019-05-17 14:09 ` Valdis Klētnieks 2019-05-17 16:19 ` Pedro Terra Delboni
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).