search

iipeace / guider

A Practically Applicable Performance Analyzer for Real Product Development
https://iipeace.github.io/docs/guider.html
GNU General Public License v2.0
629 stars 92 forks source link

Checking status for data recording #259

Open elfring opened 3 years ago

elfring commented 3 years ago

I have tried this tool out with the version 3.9.88.

[Markus_Elfring@fedora guider]$ python3 guider.py record -h
… ver_3.9.8_210923 on python_3.9
…
[ERROR] wrong command record

How does such information fit to the usage description?

iipeace commented 3 years ago

there is no "record" command, use "rec" command instead of "record".

if you wanna record events then execute commands as below.

recording features use ftrace so it is very accurate but it requires big trace buffer (memory). so if you want to measure resource usages for a long time then just use top command.

 # python3 guider/guider.py top -o guider.out

or

 # python3 guider/guider.py top -o guider.out -u -R 10s

please check varius command examples and output in README.md.

elfring commented 3 years ago

use "rec" command instead of "record".

Are you going to delete references to the other command name?

recording features use ftrace …

Would you like to add any more information for such functionality to the software documentation? (I find a description like “Record thread events” improvable.)

iipeace commented 3 years ago

Are you going to delete references to the other command name?

What do you mean? :) did you refer to old documents?

Would you like to add any more information for such functionality to the software documentation?

There are many command examples including such functionality in README.md. Did you check it? I'm thinking about writing blogs about practical performance analysis for production issues.

You can use help command to list all commands.

$ python3 guider.py help

And you can check options and examples for each command.

$ python3 guider.py [CMD] -h
elfring commented 3 years ago

What do you mean?

I suggest to reconsider the following specification once more. :thinking:

…
    $ python3 guider/guider.py record -h
    $ python3 guider/guider.py top -h
…

Did you check it?

Partly, yes.

I am looking for more helpful background information.

I'm thinking about writing blogs about practical performance analysis for production issues.

:eyes: Would you like to compare any analyses with approaches which were published also for a tool like uftrace (for example)?

iipeace commented 3 years ago

I suggest to reconsider the following specification once more.

You are right! I'm going to fix it right now :)

Would you like to compare any analyses with approaches which were published also for a tool like uftrace (for example)?

Do you want to compare features of Guider with other tools? You can refer to below contents.

elfring commented 3 years ago

Do you want to compare features of Guider with other tools?

Occasionally also for my needs, yes.

LPC21-Guider:LinuxTracingUsingPython-Doc

Would you like to improve any details in the published PDF file? :thinking:

elfring commented 3 years ago

Can execution durations be recorded for selected functions in the call hierarchy?

iipeace commented 3 years ago

Do you want to trace function calls for a specific task?

elfring commented 3 years ago

Yes, of course.

:point_right: I published analysis approaches according to special software application concerns for further development considerations.

iipeace commented 3 years ago

Guider has a function tracing feature for specific tasks. But it's overhead is not small so that I don't recommend to trace all functions.

first, you can analyze performance at function-level with sampling technique such a below command.

# python3 guider.py utop "find /" -H -o guider.out
# vi guider.out

[Top Usercall Summary] [Elapsed: 3.823] [Freq: 0.001] [SYS: 2%/121G] [find(1244621): 59%(U20%+S38%)] [guider(1244620): 38%/54M] [NrSamples: 2,081(54.4%)] [NrS
ymbols: 49]
==========================================================================================================================================================
 Usage  | Function [Path]
==========================================================================================================================================================
  32.7% | getdents64@GLIBC_2.2.5 [/usr/lib/x86_64-linux-gnu/libc-2.31.so] <Cnt: 680>
           100.0% |  <- readdir64@GLIBC_2.2.5[/usr/lib/x86_64-linux-gnu/libc-2.31.so] <- 0x261b0[/usr/bin/find] <- 0x27170[/usr/bin/find]
                     <- 0x8990[/usr/bin/find] <- 0x83e0[/usr/bin/find] <- __libc_start_main@GLIBC_2.2.5[/usr/lib/x86_64-linux-gnu/libc-2.31.so]
                     <- 0x8660[/usr/bin/find] <Cnt: 680>
  15.0% | __fxstatat@GLIBC_2.2.5 [/usr/lib/x86_64-linux-gnu/libc-2.31.so] <Cnt: 313>
            68.7% |  <- 0x255e0[/usr/bin/find] <- 0x27170[/usr/bin/find] <- 0x8990[/usr/bin/find] <- 0x83e0[/usr/bin/find]
                     <- __libc_start_main@GLIBC_2.2.5[/usr/lib/x86_64-linux-gnu/libc-2.31.so] <- 0x8660[/usr/bin/find] <Cnt: 215>
            31.3% |  <- 0x255e0[/usr/bin/find] <- 0x261b0[/usr/bin/find] <- 0x27170[/usr/bin/find] <- 0x8990[/usr/bin/find] <- 0x83e0[/usr/bin/find]
                     <- __libc_start_main@GLIBC_2.2.5[/usr/lib/x86_64-linux-gnu/libc-2.31.so] <- 0x8660[/usr/bin/find] <Cnt: 98>
  11.4% | close@GLIBC_2.4 [/usr/lib/x86_64-linux-gnu/libc-2.31.so] <Cnt: 238>
            66.8% |  <- 0x8960[/usr/bin/find] <- 0x8990[/usr/bin/find] <- 0x83e0[/usr/bin/find]
                     <- __libc_start_main@GLIBC_2.2.5[/usr/lib/x86_64-linux-gnu/libc-2.31.so] <- 0x8660[/usr/bin/find] <Cnt: 159>
            29.8% |  <- 0x25b80[/usr/bin/find] <- 0x25d80[/usr/bin/find] <- 0x27170[/usr/bin/find] <- 0x8990[/usr/bin/find] <- 0x83e0[/usr/bin/find]
                     <- __libc_start_main@GLIBC_2.2.5[/usr/lib/x86_64-linux-gnu/libc-2.31.so] <- 0x8660[/usr/bin/find] <Cnt: 71>
             3.4% |  <- 0x25b80[/usr/bin/find] <- 0x25d80[/usr/bin/find] <- 0x261b0[/usr/bin/find] <- 0x27170[/usr/bin/find] <- 0x8990[/usr/bin/find]
                     <- 0x83e0[/usr/bin/find] <- __libc_start_main@GLIBC_2.2.5[/usr/lib/x86_64-linux-gnu/libc-2.31.so] <- 0x8660[/usr/bin/find] <Cnt: 8>
   9.7% | openat64@GLIBC_2.2.5 [/usr/lib/x86_64-linux-gnu/libc-2.31.so] <Cnt: 202>
            96.0% |  <- 0x39dd0[/usr/bin/find] <- 0x39e50[/usr/bin/find] <- 0x261b0[/usr/bin/find] <- 0x27170[/usr/bin/find] <- 0x8990[/usr/bin/find]
                     <- 0x83e0[/usr/bin/find] <- __libc_start_main@GLIBC_2.2.5[/usr/lib/x86_64-linux-gnu/libc-2.31.so] <- 0x8660[/usr/bin/find] <Cnt: 194>
             4.0% |  <- 0x39dd0[/usr/bin/find] <- 0x25d80[/usr/bin/find] <- 0x27170[/usr/bin/find] <- 0x8990[/usr/bin/find] <- 0x83e0[/usr/bin/find]
                     <- __libc_start_main@GLIBC_2.2.5[/usr/lib/x86_64-linux-gnu/libc-2.31.so] <- 0x8660[/usr/bin/find] <Cnt: 8>
   7.3% | 0x116580 [/usr/lib/x86_64-linux-gnu/libc-2.31.so] <Cnt: 152>
            58.6% |  <- fcntl@GLIBC_2.2.5[/usr/lib/x86_64-linux-gnu/libc-2.31.so] <- 0x25220[/usr/bin/find] <- 0x88e0[/usr/bin/find]
                     <- 0x8990[/usr/bin/find] <- 0x83e0[/usr/bin/find] <- __libc_start_main@GLIBC_2.2.5[/usr/lib/x86_64-linux-gnu/libc-2.31.so]
                     <- 0x8660[/usr/bin/find] <Cnt: 89>
            41.4% |  <- fcntl@GLIBC_2.2.5[/usr/lib/x86_64-linux-gnu/libc-2.31.so] <- 0x25220[/usr/bin/find] <- 0x261b0[/usr/bin/find]
                     <- 0x27170[/usr/bin/find] <- 0x8990[/usr/bin/find] <- 0x83e0[/usr/bin/find]
                     <- __libc_start_main@GLIBC_2.2.5[/usr/lib/x86_64-linux-gnu/libc-2.31.so] <- 0x8660[/usr/bin/find] <Cnt: 63>
----------------------------------------------------------------------------------------------------------------------------------------------------------

then you can know which function takes long time. It will be very useful if you convert guider.out to flame graph in SVG format and open it in your web browser.

$ python3 guider.py drawflame guider.out

   _____       _     _
  / ____|     (_)   | |
 | |  __ _   _ _  __| | ___ _ __
 | | |_ | | | | |/ _` |/ _ \ '__|
 | |__| | |_| | | (_| |  __/ |
  \_____|\__,_|_|\__,_|\___|_|  ver_3.9.8_210926 on python_3.8

[STEP] start checking 'guider.out' [69.0K]...

[INFO] saved flamegraph into '/home/peacelee/guider/guider/guider_flamegraph.svg' [34.3K] successfully

finally, if you want to trace specific functions then use a below command.

# python3 guider.py btrace "find /" -H -c  getdents64

or 

# python3 guider.py btrace "find /" -H -c  getdents64 -o
# vi guider.out

[Trace Breakcall Summary] [Elapsed: 2.279] [find(1244635)] [guider(1244634)] [NrSamples: 1,254] [NrSymbols: 1]
==========================================================================================================================================================
 Usage  | Function [PATH] <Elapsed>
==========================================================================================================================================================
 100.0% | getdents64 [/usr/lib/x86_64-linux-gnu/libc-2.31.so] <Cnt: 1,254, Elapsed: 0.013828, Avg: 0.000011, Min: 0.000010, Max: 0.000123>
----------------------------------------------------------------------------------------------------------------------------------------------------------

[elapsed Histogram] (unit:us)
==========================================================================================================================================================
        Range                 Count
----------------------------------------------------------------------------------------------------------------------------------------------------------
8,192     -    16,383            1(100.0%)
----------------------------------------------------------------------------------------------------------------------------------------------------------
         Min                       13,827
         Max                       13,827
         Cnt                            1
----------------------------------------------------------------------------------------------------------------------------------------------------------

[Trace History] [find(1244635)] [Time: 2.279424] [Line: 2,507]
==========================================================================================================================================================

         0x8660/0x55d062e0f68e [/usr/bin/find]
           __libc_start_main@GLIBC_2.2.5/0x7f290327d0b3 [/usr/lib/x86_64-linux-gnu/libc-2.31.so]
             0x83e0/0x55d062e0f52a [/usr/bin/find]
               0x8990/0x55d062e0fa52 [/usr/bin/find]
                 0x27170/0x55d062e2e57d [/usr/bin/find]
                   0x261b0/0x55d062e2d346 [/usr/bin/find]
                     readdir64@GLIBC_2.2.5/0x7f29033374f5 [/usr/lib/x86_64-linux-gnu/libc-2.31.so]
0.032033               getdents64/0x7f2903337420(0x4,0x55d063b823b0,0x8000,0x100,0x30,0x1) [/usr/lib/x86_64-linux-gnu/libc-2.31.so]

0.032059               getdents64[RET]=0x2c0(704)/0.000026 -> readdir64@GLIBC_2.2.5/0x7f2903256000 [/usr/lib/x86_64-linux-gnu/libc-2.31.so]

0.032070               getdents64/0x7f2903337420(0x4,0x55d063b823b0,0x8000,0x100,0x2f0,0x1) [/usr/lib/x86_64-linux-gnu/libc-2.31.so]

0.032081               getdents64[RET]=0x0(0)/0.000011 -> readdir64@GLIBC_2.2.5/0x7f2903256000 [/usr/lib/x86_64-linux-gnu/libc-2.31.so]

0.032108               getdents64/0x7f2903337420(0x6,0x55d063b823b0,0x8000,0x100,0x30,0x1) [/usr/lib/x86_64-linux-gnu/libc-2.31.so]

0.032139               getdents64[RET]=0x250(592)/0.000031 -> readdir64@GLIBC_2.2.5/0x7f2903256000 [/usr/lib/x86_64-linux-gnu/libc-2.31.so]

0.032150               getdents64/0x7f2903337420(0x6,0x55d063b823b0,0x8000,0x100,0x280,0x1) [/usr/lib/x86_64-linux-gnu/libc-2.31.so]

0.032161               getdents64[RET]=0x0(0)/0.000011 -> readdir64@GLIBC_2.2.5/0x7f2903256000 [/usr/lib/x86_64-linux-gnu/libc-2.31.so]

0.032186               getdents64/0x7f2903337420(0x6,0x55d063b823b0,0x8000,0x100,0x30,0x1) [/usr/lib/x86_64-linux-gnu/libc-2.31.so]

0.032197               getdents64[RET]=0x48(72)/0.000011 -> readdir64@GLIBC_2.2.5/0x7f2903256000 [/usr/lib/x86_64-linux-gnu/libc-2.31.so]

0.032208               getdents64/0x7f2903337420(0x6,0x55d063b823b0,0x8000,0x100,0x78,0x1) [/usr/lib/x86_64-linux-gnu/libc-2.31.so]

0.032218               getdents64[RET]=0x0(0)/0.000010 -> readdir64@GLIBC_2.2.5/0x7f2903256000 [/usr/lib/x86_64-linux-gnu/libc-2.31.so]

0.032250               getdents64/0x7f2903337420(0x6,0x55d063b8d350,0x8000,0x100,0x30,0x1) [/usr/lib/x86_64-linux-gnu/libc-2.31.so]

0.032260               getdents64[RET]=0x48(72)/0.000011 -> readdir64@GLIBC_2.2.5/0x7f2903256000 [/usr/lib/x86_64-linux-gnu/libc-2.31.so]

check [RET]=RETURN_VALUE/ELAPSED_TIME for each line.

iipeace commented 3 years ago

in addition, you can profile or trace running tasks with -g option.

# sleep 30 &
# python3 guider.py utop -g sleep -H

# sleep 20 &
# python3 guider.py btrace -g sleep -H
elfring commented 3 years ago

But it's overhead is not small so that I don't recommend to trace all functions.

Thanks for such a warning.

first, you can analyze performance at function-level with sampling technique such a below command.

Will such background information become better represented in the evolving software documentation?

check [RET]=RETURN_VALUE/ELAPSED_TIME for each line.

Would you like to extend any help descriptions accordingly?

Which data structures are provided by a file like “guider.out”?

I became especially interested in further clarification for repeated calls of the function “statvfs64” (which gets called also by the function “QStorageInfoPrivate::retrieveVolumeInfo” for example). Would you find the total test program execution durations questionable occasionally? :thinking:

iipeace commented 3 years ago

Will such background information become better represented in the evolving software documentation?

I will try! :)

Would you like to extend any help descriptions accordingly? Which data structures are provided by a file like “guider.out”?

0.032208               getdents64/0x7f2903337420(0x6,0x55d063b823b0,0x8000,0x100,0x78,0x1) [/usr/lib/x86_64-linux-gnu/libc-2.31.so]
0.032218               getdents64[RET]=0x0(0)/0.000010 -> readdir64@GLIBC_2.2.5/0x7f2903256000 [/usr/lib/x86_64-linux-gnu/libc-2.31.so]

first line describes call info of the target function "getdents64". second line describes return info of the target function "getdents64". the call elapsed about 0.000010 (10us) and returned 0x0.

Would you find the total test program execution durations questionable occasionally? as I explained profiling way using Guider, first, Identify the function calls that make up the most weight, second, trace the function calls including backtraces for elapsed time and call count. I think you can also find the result using this way even though target tasks are already running.

the total test program execution durations that you mentioned are very nice and accurate. but the function tracing feature of Guider has a overhead so that finding accurate execution durations is difficult.

elfring commented 3 years ago

but the function tracing feature of Guider has a overhead so that finding accurate execution durations is difficult.

Does this feedback express a target conflict for desirable precise software run time analyses?

iipeace commented 3 years ago

yes, measuring some kind of function calls is good! But all function tracing will may consume so much time as you can test it :)

elfring commented 3 years ago

I tried it out already to measure run time characteristics for selected function call hierarchies (including calls for Linux kernel functions). :crystal_ball: How are the chances to reduce undesirable influences of (Python) software components any further for efficient measurements?

iipeace commented 3 years ago

The biggest cause of the overhead is not about python code. It's about the cost for ptrace mechanism. it has no requirement such as build option, restart, kernel option for target system even though it has overhead.