From: Jean-Guillaume P. (LMC)
<Jea...@er...> - 2003-03-24 16:37:19
|
Hi all, I've recently discovered Oprofile and I must say it is a very nice tool. However, I do not know how to understand some of my results. Here is an example: --------------------------------- inline int internal_sk_buff_alloc_security(struct sk_buff *skb) /* internal_sk_buff_alloc_security 1882 12.48% */ /* 353 2.342% */ { sk_buff_security_t *sksec; /* 15 0.0995% */ int rc = 0; /* 10 0.06633% */ sksec = skb->lsm_security; /* 468 3.104% */ if (sksec && sksec->magic == DSI_MAGIC) { goto out; } sksec = (sk_buff_security_t *) get_sk_buff_memory(skb); /* 3 0.0199% */ if (!sksec) { /* 38 0.2521% */ rc = -ENOMEM; goto out; /* 10 0.06633% */ } memset(sksec, 0, sizeof (sk_buff_security_t)); /* 44 0.2919% */ sksec->magic = DSI_MAGIC; /* 32 0.2123% */ sksec->skb = skb; /* 45 0.2985% */ sksec->sid = DSI_SID_NORMAL; /* 31 0.2056% */ skb->lsm_security = sksec; out: /* 146 0.9685% */ return rc; /* 98 0.6501% */ } ------------------------------------------ It seems the program has spent 1882 samples in this function. However, the line after, there is a /* 353 2.342% */ . What is this for? And after that, I fail to see where are the 1882 samples in the function! :( What am I missing here? Jean-Guillaume |
From: Jean-Guillaume P. (LMC)
<Jea...@er...> - 2003-03-24 17:44:03
|
(**) I sent this same mail from the wrong adress 20 min ago, so if you got any duplicate I am sorry!!! Hi all, I've recently discovered Oprofile and I must say it is a very nice tool. However, I do not know how to understand some of my results. Here is an example: --------------------------------- inline int internal_sk_buff_alloc_security(struct sk_buff *skb) /* internal_sk_buff_alloc_security 1882 12.48% */ /* 353 2.342% */ { sk_buff_security_t *sksec; /* 15 0.0995% */ int rc = 0; /* 10 0.06633% */ sksec = skb->lsm_security; /* 468 3.104% */ if (sksec && sksec->magic == DSI_MAGIC) { goto out; } sksec = (sk_buff_security_t *) get_sk_buff_memory(skb); /* 3 0.0199% */ if (!sksec) { /* 38 0.2521% */ rc = -ENOMEM; goto out; /* 10 0.06633% */ } memset(sksec, 0, sizeof (sk_buff_security_t)); /* 44 0.2919% */ sksec->magic = DSI_MAGIC; /* 32 0.2123% */ sksec->skb = skb; /* 45 0.2985% */ sksec->sid = DSI_SID_NORMAL; /* 31 0.2056% */ skb->lsm_security = sksec; out: /* 146 0.9685% */ return rc; /* 98 0.6501% */ } ------------------------------------------ It seems the program has spent 1882 samples in this function. However, the line after, there is a /* 353 2.342% */ . What is this for? And after that, I fail to see where are the 1882 samples in the function! :( What am I missing here? Jean-Guillaume |
From: John L. <le...@mo...> - 2003-03-24 18:13:41
|
On Mon, Mar 24, 2003 at 11:35:12AM -0500, Jean-Guillaume Paradis (LMC) wrote: > inline int > internal_sk_buff_alloc_security(struct sk_buff *skb) > /* internal_sk_buff_alloc_security 1882 12.48% */ > /* 353 2.342% */ > { > [snip] > /* 98 0.6501% */ > > > It seems the program has spent 1882 samples in this function. > > However, the line after, there is a /* 353 2.342% */ . What is this for? That generally means the samples at the start of the function (prologue etc.) > And after that, I fail to see where are the 1882 samples in the > function! :( > > What am I missing here? It's rather obscure I'm afraid, but these "missing" samples are credited elsewhere in functions that were inlined into this function. Phil, do we document this ? regards john |
From: Philippe E. <ph...@wa...> - 2003-03-24 18:30:38
|
Jean-Guillaume Paradis (LMC) wrote: > Arrgh :( np :) > Hi all, > > I've recently discovered Oprofile and I must say it is a very nice > tool. However, I do not know how to understand some of my results. Here > is an example: > > --------------------------------- > > inline int > internal_sk_buff_alloc_security(struct sk_buff *skb) > /* internal_sk_buff_alloc_security 1882 12.48% */ this function is credited by 1882 samples > /* 353 2.342% */ the prolog code of this function is credited by 353 samples (on x86 push registers, setup stack frame and base frame pointer) > { > > sk_buff_security_t *sksec; > /* 15 0.0995% */ > int rc = 0; > > /* 10 0.06633% */ > sksec = skb->lsm_security; > /* 468 3.104% */ the high cost here is probably a cache fault on sksec->magic access, a branch misprediction or perhaps but unlikely a pipline stalls > if (sksec && sksec->magic == DSI_MAGIC) { > goto out; > } > > sksec = (sk_buff_security_t *) get_sk_buff_memory(skb); > /* 3 0.0199% */ > if (!sksec) { > /* 38 0.2521% */ > rc = -ENOMEM; > goto out; > /* 10 0.06633% */ > } look here no samples for memset call ? see later. > memset(sksec, 0, sizeof (sk_buff_security_t)); > /* 44 0.2919% */ > sksec->magic = DSI_MAGIC; > /* 32 0.2123% */ > sksec->skb = skb; > /* 45 0.2985% */ > sksec->sid = DSI_SID_NORMAL; > /* 31 0.2056% */ > skb->lsm_security = sksec; > > out: > > /* 146 0.9685% */ > return rc; > > /* 98 0.6501% */ here it's the epilog code of the function > } > > > ------------------------------------------ > > It seems the program has spent 1882 samples in this function. > > However, the line after, there is a /* 353 2.342% */ . What is this for? > > And after that, I fail to see where are the 1882 samples in the > function! :( some function call in this function are inlined (likely to be the memset call) at assembly point of view the function get 1882 samples but at source point of view the samples for the inlined call go to the memset source. This why you don't see any samples at memset call site If you want more accurate things try -a or -s option to op_to_source, this will give assembly (-a) or assembly mixed with source (-s), if all thing go right you will see the 1882 samples at assembly level. -s can be confusing cause you will see sample for source and for assembly so you will see more samples than expected > > What am I missing here? nothing except the missing part in documentation. There is also a few other problem documented here http://oprofile.sourceforge.net/doc/interpreting.html inlined call is the thing that op_to_source handle the more poorly... regards, Phil |
From: Jean-Guillaume P. (LMC)
<Jea...@er...> - 2003-03-24 18:58:38
|
Philippe and John: Now THAT'S what I call an helpful reply, and a quick one that is. Many thanks to you two, and keep up the good work on your project. Programs/kernel profiling tools is an area that is kinda lacking under Linux from what I have seen, and Oprofile fits in nicely to fill this gap. It is also great that the kernel doesn't need to get patched for the kernel profiling to work (ala LTT and KernProf), which has caused me some problems in the past. Proper usage of your tool will help to speed up the development/optimization of applications and kernels for many persons. :) Philippe, perhaps you could keep your reply verbatim somewhere, and use it for your doc in the future, I'm sure this explanation of the workings of Oprofile would be useful to many persons! Have a nice day, Jean-Guillaume |
From: John L. <le...@mo...> - 2003-03-24 19:38:53
|
On Mon, Mar 24, 2003 at 01:56:32PM -0500, Jean-Guillaume Paradis (LMC) wrote: > Philippe, perhaps you could keep your reply verbatim somewhere, and use > it for your doc in the future, I'm sure this explanation of the workings > of Oprofile would be useful to many persons! I've added some text to the manual, including your example : http://www.movement.uklinux.net/oprofile.html#prologues I assume this code is GPL'd so it's OK to include the manual, since from the looks of it you're working on the Ericsson LSM module ? regards, john |
From: Jean-Guillaume P. (LMC)
<Jea...@er...> - 2003-03-24 19:44:56
|
> I assume this code is GPL'd so it's OK to include the manual, since from > the looks of it you're working on the Ericsson LSM module ? > > regards, > john Indeed, so no problems :) Jean-Guillaume |