Checking status for data recording #259

elfring · 2021-09-24T19:36:52Z

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?

The text was updated successfully, but these errors were encountered:

iipeace · 2021-09-25T00:37:04Z

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

if you wanna record events then execute commands as below.

record events including I/O and report to stdout

# python3 guider/guider.py iorec -a

record events including I/O and report to the specific file.

# python3 guider/guider.py iorec -s guider.dat
# python3 guider/guider.py report guider.out -o guider.out -a

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 · 2021-09-25T05:36:19Z

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 · 2021-09-25T11:34:36Z

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 · 2021-09-25T12:33:33Z

What do you mean?

I suggest to reconsider the following specification once more. 🤔

…
    $ 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.

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

iipeace · 2021-09-25T13:22:53Z

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 · 2021-09-25T16:25:13Z

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? 🤔

I got used to the aspect that typographic quotation characters are seldom applied for strings in the shown commands.
I suggest to fix the link to your issue tracker on the question page at the end.

elfring · 2021-09-25T17:30:30Z

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

iipeace · 2021-09-26T03:40:52Z

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

elfring · 2021-09-26T07:12:18Z

Yes, of course.

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

iipeace · 2021-09-27T11:36:41Z

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 · 2021-09-27T12:00:53Z

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 · 2021-09-27T14:10:14Z

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? 🤔

iipeace · 2021-09-27T15:10:50Z

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 · 2021-09-27T17:04:11Z

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 · 2021-09-27T21:47:40Z

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 · 2021-09-28T06:50:38Z

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

iipeace · 2021-09-29T06:31:19Z

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.

iipeace self-assigned this Sep 25, 2021

iipeace added the question label Sep 25, 2021

elfring mentioned this issue Sep 30, 2021

Export tracing records in rows instead of multi-line structures #271

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Checking status for data recording #259

Checking status for data recording #259

elfring commented Sep 24, 2021

iipeace commented Sep 25, 2021 •

edited

Loading

elfring commented Sep 25, 2021 •

edited

Loading

iipeace commented Sep 25, 2021

elfring commented Sep 25, 2021

iipeace commented Sep 25, 2021 •

edited

Loading

elfring commented Sep 25, 2021

elfring commented Sep 25, 2021

iipeace commented Sep 26, 2021

elfring commented Sep 26, 2021

iipeace commented Sep 27, 2021

iipeace commented Sep 27, 2021

elfring commented Sep 27, 2021

iipeace commented Sep 27, 2021

elfring commented Sep 27, 2021

iipeace commented Sep 27, 2021

elfring commented Sep 28, 2021

iipeace commented Sep 29, 2021

Checking status for data recording #259

Checking status for data recording #259

Comments

elfring commented Sep 24, 2021

iipeace commented Sep 25, 2021 • edited Loading

elfring commented Sep 25, 2021 • edited Loading

iipeace commented Sep 25, 2021

elfring commented Sep 25, 2021

iipeace commented Sep 25, 2021 • edited Loading

elfring commented Sep 25, 2021

elfring commented Sep 25, 2021

iipeace commented Sep 26, 2021

elfring commented Sep 26, 2021

iipeace commented Sep 27, 2021

iipeace commented Sep 27, 2021

elfring commented Sep 27, 2021

iipeace commented Sep 27, 2021

elfring commented Sep 27, 2021

iipeace commented Sep 27, 2021

elfring commented Sep 28, 2021

iipeace commented Sep 29, 2021

iipeace commented Sep 25, 2021 •

edited

Loading

elfring commented Sep 25, 2021 •

edited

Loading

iipeace commented Sep 25, 2021 •

edited

Loading