One: [onert] Support ChromeTracingObserver to print out as table format

[YongseopKim]

Current ChromeTracingObserver writes the event records to file as json format. It could also do it as table format.

cc @wateret and @chunseoklee

[YongseopKim]

version 1

traceEvents

durationEvents

|name|pid|tid|ph|ts|
|---|---|---|---|---|
|Graph|0|runtime|B|934082273606|
|$0 Conv2D (+5)|0|cpu|B|934082274473|
|$0 Conv2D (+5)|0|cpu|E|934083981355|
|$6 Conv2D (+2)|0|cpu|B|934083981511|
|$6 Conv2D (+2)|0|cpu|E|934084495729|
|$9 Add (+3)|0|cpu|B|934084495885|
|$9 Add (+3)|0|cpu|E|934084687335|
|$13 Conv2D (+2)|0|cpu|B|934084687447|
|$13 Conv2D (+2)|0|cpu|E|934084885146|
|$16 Add|0|cpu|B|934084885304|
|$16 Add|0|cpu|E|934084885652|
|$17 Conv2D (+2)|0|cpu|B|934084885720|
|$17 Conv2D (+2)|0|cpu|E|934085078280|
|$20 Add (+3)|0|cpu|B|934085078391|
|$20 Add (+3)|0|cpu|E|934085162863|
|$24 Conv2D (+2)|0|cpu|B|934085162959|
|$24 Conv2D (+2)|0|cpu|E|934085318074|
|$27 Add|0|cpu|B|934085318220|
|$27 Add|0|cpu|E|934085318454|
|$28 Conv2D (+2)|0|cpu|B|934085318514|
|$28 Conv2D (+2)|0|cpu|E|934085446090|
|$31 Add|0|cpu|B|934085446182|
|$31 Add|0|cpu|E|934085446415|
|$32 Conv2D (+2)|0|cpu|B|934085446475|
|$32 Conv2D (+2)|0|cpu|E|934085589104|
|$35 Add (+3)|0|cpu|B|934085589197|
|$35 Add (+3)|0|cpu|E|934085728572|
|$39 Conv2D (+2)|0|cpu|B|934085728666|
|$39 Conv2D (+2)|0|cpu|E|934085966500|
|$42 Add|0|cpu|B|934085966605|
|$42 Add|0|cpu|E|934085966880|
|$43 Conv2D (+2)|0|cpu|B|934085966945|
|$43 Conv2D (+2)|0|cpu|E|934086201595|
|$46 Add (+3)|0|cpu|B|934086201771|
|$46 Add (+3)|0|cpu|E|934086329017|
|$50 Conv2D (+2)|0|cpu|B|934086329118|
|$50 Conv2D (+2)|0|cpu|E|934086455768|
|$53 Add|0|cpu|B|934086455873|
|$53 Add|0|cpu|E|934086456104|
|$54 Conv2D (+2)|0|cpu|B|934086456165|
|$54 Conv2D (+2)|0|cpu|E|934086582420|
|$57 Add (+8)|0|cpu|B|934086582525|
|$57 Add (+8)|0|cpu|E|934086972418|
|$66 Permute|0|controlflow|B|934086972537|
|$66 Permute|0|controlflow|E|934086973109|
|Graph|0|runtime|E|934086973176|

counterEvents

|name|pid|tid|ph|ts|args-value|
|---|---|---|---|---|---|
|maxrss|0||C|934082273606|83144|
|minflt|0||C|934082273606|9422|
|maxrss|0||C|934082274473|83144|
|minflt|0||C|934082274473|9422|
|maxrss|0||C|934083981355|85072|
|minflt|0||C|934083981355|10742|
|maxrss|0||C|934083981511|85072|
|minflt|0||C|934083981511|10742|
|maxrss|0||C|934084495729|85352|
|minflt|0||C|934084495729|11268|
|maxrss|0||C|934084495885|85352|
|minflt|0||C|934084495885|11268|
|maxrss|0||C|934084687335|85352|
|minflt|0||C|934084687335|11387|
|maxrss|0||C|934084687447|85352|
|minflt|0||C|934084687447|11387|
|maxrss|0||C|934084885146|85352|
|minflt|0||C|934084885146|11545|
|maxrss|0||C|934084885304|85352|
|minflt|0||C|934084885304|11545|
|maxrss|0||C|934084885652|85352|
|minflt|0||C|934084885652|11545|
|maxrss|0||C|934084885720|85352|
|minflt|0||C|934084885720|11545|
|maxrss|0||C|934085078280|85352|
|minflt|0||C|934085078280|11703|
|maxrss|0||C|934085078391|85352|
|minflt|0||C|934085078391|11703|
|maxrss|0||C|934085162863|85352|
|minflt|0||C|934085162863|11707|
|maxrss|0||C|934085162959|85352|
|minflt|0||C|934085162959|11707|
|maxrss|0||C|934085318074|85352|
|minflt|0||C|934085318074|11815|
|maxrss|0||C|934085318220|85352|
|minflt|0||C|934085318220|11815|
|maxrss|0||C|934085318454|85352|
|minflt|0||C|934085318454|11815|
|maxrss|0||C|934085318514|85352|
|minflt|0||C|934085318514|11815|
|maxrss|0||C|934085446090|85352|
|minflt|0||C|934085446090|11854|
|maxrss|0||C|934085446182|85352|
|minflt|0||C|934085446182|11854|
|maxrss|0||C|934085446415|85352|
|minflt|0||C|934085446415|11854|
|maxrss|0||C|934085446475|85352|
|minflt|0||C|934085446475|11854|
|maxrss|0||C|934085589104|85352|
|minflt|0||C|934085589104|11858|
|maxrss|0||C|934085589197|85352|
|minflt|0||C|934085589197|11858|
|maxrss|0||C|934085728572|85352|
|minflt|0||C|934085728572|11885|
|maxrss|0||C|934085728666|85352|
|minflt|0||C|934085728666|11885|
|maxrss|0||C|934085966500|85352|
|minflt|0||C|934085966500|11898|
|maxrss|0||C|934085966605|85352|
|minflt|0||C|934085966605|11898|
|maxrss|0||C|934085966880|85352|
|minflt|0||C|934085966880|11898|
|maxrss|0||C|934085966945|85352|
|minflt|0||C|934085966945|11898|
|maxrss|0||C|934086201595|85352|
|minflt|0||C|934086201595|11902|
|maxrss|0||C|934086201771|85352|
|minflt|0||C|934086201771|11902|
|maxrss|0||C|934086329017|85352|
|minflt|0||C|934086329017|11990|
|maxrss|0||C|934086329118|85352|
|minflt|0||C|934086329118|11990|
|maxrss|0||C|934086455768|85556|
|minflt|0||C|934086455768|12208|
|maxrss|0||C|934086455873|85556|
|minflt|0||C|934086455873|12208|
|maxrss|0||C|934086456104|85556|
|minflt|0||C|934086456104|12208|
|maxrss|0||C|934086456165|85556|
|minflt|0||C|934086456165|12208|
|maxrss|0||C|934086582420|85556|
|minflt|0||C|934086582420|12391|
|maxrss|0||C|934086582525|85556|
|minflt|0||C|934086582525|12391|
|maxrss|0||C|934086972418|86944|
|minflt|0||C|934086972418|13162|
|maxrss|0||C|934086972537|86944|
|minflt|0||C|934086972537|13162|
|maxrss|0||C|934086973109|86944|
|minflt|0||C|934086973109|13162|
|maxrss|0||C|934086973176|86944|
|minflt|0||C|934086973176|13162|

Hmm... something should be changed... it looks not helpful for anyone.

[YongseopKim]

durationEvents

• each Graph(Warm-up and Run of nnpackage_run) has a table in durationEvents
• an op's time shows the only diff(ts of E and ts of B)

counterEvents

• if possible, maxrss and minflt would be included in each op

[YongseopKim]

maybe like this

traceEvents

Graph 0 (935616739825~935620644171)

|latency(us)|rss_min(kb)|rss_max(kb)|page_reclaims_min|page_reclaims_max|
|-----------|-----------|-----------|-----------------|-----------------|
| 4699570 | 83144 | 83144 | 9422 | 9422 |

OpSequences

| OpSeq_name | pid | backend |latency(us)|rss_min(kb)|rss_max(kb)|page_reclaims_min|page_reclaims_max|
|----------------|-----|-----|-----------|-----------|-----------|-----------------|-----------------|
| $0 Conv2D (+5) | 0 | cpu |911422 | 83144 | 83144 | 9422 | 9422 |
| $9 Add (+3) | 0 | cpu |911422 | 83144 | 83144 | 9422 | 9422 |

Graph 1 (935620644277~935624511826)

|latency(us)|rss_min(kb)|rss_max(kb)|page_reclaims_min|page_reclaims_max|
|-----------|-----------|-----------|-----------------|-----------------|
| 4699570 | 83144 | 83144 | 9422 | 9422 |

OpSequences

| OpSeq_name | pid | backend |latency(us)|rss_min(kb)|rss_max(kb)|page_reclaims_min|page_reclaims_max|
|----------------|-----|-----|-----------|-----------|-----------|-----------------|-----------------|
| $0 Conv2D (+5) | 0 | cpu |911422 | 83144 | 83144 | 9422 | 9422 |
| $9 Add (+3) | 0 | cpu |911422 | 83144 | 83144 | 9422 | 9422 |

[wateret]

@YongseopKim You may refer to EventRecorder::writeSNPEBenchmark impl, which contains duration calculation.

[YongseopKim]

New Template

odroid@odroid:/home/dragon/Works/github/ONE$ TRACE_FILEPATH=trace ./Product/out/bin/nnpackage_run ./benchmark_nnpkg_models/mobilenet_v2_1.0_224/ -w1 -r1

Graph 0

| latency(us) | rss_min(kb) | rss_max(kb) | page_reclaims_min | page_reclaims_max |
| ----------- | ------- | ------- | ----------------- | ----------------- |
| 4066352 | 83348 | 87224 | 9396 | 13136 |

OpSequences

| OpSeq name | backend | latency(us) | latency(%) | rss_min(kb) | rss_max(kb) | page_reclaims_min | page_reclaims_max |
| ---------- | ------- | ----------- | ----------- | ------- | ------- | ----------------- | ----------------- |
| $0 Conv2D (+5) | cpu | 927928 | 22.819667 | 83348 | 84820 | 9396 | 10717 |
| $6 Conv2D (+2) | cpu | 630718 | 15.510659 | 84820 | 85892 | 10717 | 11243 |
| $9 Add (+3) | cpu | 195427 | 4.805954 | 85892 | 85892 | 11243 | 11362 |
| $13 Conv2D (+2) | cpu | 188139 | 4.626727 | 85892 | 85892 | 11362 | 11520 |
| $16 Add | cpu | 385 | 0.009468 | 85892 | 85892 | 11520 | 11520 |
| $17 Conv2D (+2) | cpu | 191235 | 4.702864 | 85892 | 85892 | 11520 | 11678 |
| $20 Add (+3) | cpu | 83678 | 2.057815 | 85892 | 85892 | 11678 | 11682 |
| $24 Conv2D (+2) | cpu | 131050 | 3.222790 | 85892 | 85892 | 11682 | 11790 |
| $27 Add | cpu | 240 | 0.005902 | 85892 | 85892 | 11790 | 11790 |
| $28 Conv2D (+2) | cpu | 137598 | 3.383819 | 85892 | 85892 | 11790 | 11829 |
| $31 Add | cpu | 217 | 0.005336 | 85892 | 85892 | 11829 | 11829 |
| $32 Conv2D (+2) | cpu | 130066 | 3.198592 | 85892 | 85892 | 11829 | 11833 |
| $35 Add (+3) | cpu | 164013 | 4.033419 | 85892 | 85892 | 11833 | 11860 |
| $39 Conv2D (+2) | cpu | 235613 | 5.794211 | 85892 | 85892 | 11860 | 11874 |
| $42 Add | cpu | 366 | 0.009001 | 85892 | 85892 | 11874 | 11874 |
| $43 Conv2D (+2) | cpu | 269760 | 6.633956 | 85892 | 85892 | 11874 | 11878 |
| $46 Add (+3) | cpu | 126433 | 3.109249 | 85892 | 85892 | 11878 | 11966 |
| $50 Conv2D (+2) | cpu | 157829 | 3.881341 | 85892 | 86100 | 11966 | 12184 |
| $53 Add | cpu | 176 | 0.004328 | 86100 | 86100 | 12184 | 12184 |
| $54 Conv2D (+2) | cpu | 127029 | 3.123906 | 86100 | 86364 | 12184 | 12366 |
| $57 Add (+8) | cpu | 364519 | 8.964276 | 86364 | 87224 | 12366 | 13136 |
| $66 Permute | controlflow | 563 | 0.013845 | 87224 | 87224 | 13136 | 13136 |

Graph 1

| latency(us) | rss_min(kb) | rss_max(kb) | page_reclaims_min | page_reclaims_max |
| ----------- | ------- | ------- | ----------------- | ----------------- |
| 3834331 | 87224 | 87476 | 13136 | 16204 |

OpSequences

| OpSeq name | backend | latency(us) | latency(%) | rss_min(kb) | rss_max(kb) | page_reclaims_min | page_reclaims_max |
| ---------- | ------- | ----------- | ----------- | ------- | ------- | ----------------- | ----------------- |
| $0 Conv2D (+5) | cpu | 931600 | 24.296285 | 87224 | 87476 | 13136 | 14356 |
| $6 Conv2D (+2) | cpu | 518184 | 13.514326 | 87476 | 87476 | 14356 | 14801 |
| $9 Add (+3) | cpu | 192085 | 5.009609 | 87476 | 87476 | 14801 | 14801 |
| $13 Conv2D (+2) | cpu | 187566 | 4.891753 | 87476 | 87476 | 14801 | 14955 |
| $16 Add | cpu | 379 | 0.009884 | 87476 | 87476 | 14955 | 14955 |
| $17 Conv2D (+2) | cpu | 192237 | 5.013573 | 87476 | 87476 | 14955 | 15109 |
| $20 Add (+3) | cpu | 83711 | 2.183197 | 87476 | 87476 | 15109 | 15109 |
| $24 Conv2D (+2) | cpu | 125506 | 3.273218 | 87476 | 87476 | 15109 | 15109 |
| $27 Add | cpu | 280 | 0.007302 | 87476 | 87476 | 15109 | 15109 |
| $28 Conv2D (+2) | cpu | 128589 | 3.353623 | 87476 | 87476 | 15109 | 15109 |
| $31 Add | cpu | 292 | 0.007615 | 87476 | 87476 | 15109 | 15109 |
| $32 Conv2D (+2) | cpu | 143437 | 3.740861 | 87476 | 87476 | 15109 | 15109 |
| $35 Add (+3) | cpu | 142722 | 3.722214 | 87476 | 87476 | 15109 | 15120 |
| $39 Conv2D (+2) | cpu | 230982 | 6.024050 | 87476 | 87476 | 15120 | 15125 |
| $42 Add | cpu | 313 | 0.008163 | 87476 | 87476 | 15125 | 15125 |
| $43 Conv2D (+2) | cpu | 233787 | 6.097204 | 87476 | 87476 | 15125 | 15125 |
| $46 Add (+3) | cpu | 124940 | 3.258456 | 87476 | 87476 | 15125 | 15125 |
| $50 Conv2D (+2) | cpu | 128168 | 3.342643 | 87476 | 87476 | 15125 | 15283 |
| $53 Add | cpu | 208 | 0.005425 | 87476 | 87476 | 15283 | 15283 |
| $54 Conv2D (+2) | cpu | 138996 | 3.625039 | 87476 | 87476 | 15283 | 15441 |
| $57 Add (+8) | cpu | 327868 | 8.550853 | 87476 | 87476 | 15441 | 16204 |
| $66 Permute | controlflow | 164 | 0.004277 | 87476 | 87476 | 16204 | 16204 |

[YongseopKim]

ONE's current trace system prints the only one file format - such as one of json, mdtable and snpe - and the choice for the file format could be modified on the code level.

For supporting all of the file formats, we could introduce one of below things

1. just prints all of the file formats with modifying TRACE_FILEPATH.
   
   
   
   • For example, if TRACE_FILEPATH=my_trace, prints contents to my_trace.json as json, to my_trace.md as mdtable and to my_trace.snpe as snpe.
   
   
2. new config option for the file format such as TRACE_FILE_FORMAT=json
   
   
   
   • TRACE_FILEPATH=my_trace and TRACE_FILE_FORMAT=json -> prints content to my_trace as json
   
   
3. or parsing TRACE_FILEPATH and if it has json as extension, it would be dealt as json. If it has no extention, prints all of file format.

Any idea @chunseoklee and @wateret ?

[wateret]

just prints all of the file formats with modifying TRACE_FILEPATH.
For example, if TRACE_FILEPATH=my_trace, prints contents to my_trace.json as json, to my_trace.md as mdtable and to my_trace.snpe as snpe.

I would prefer this way, since we don't need extra work for code coverage, and we don't have to add more env options. And I think there is no harm to write in those 3 formats. If it gets more formats, we should think about it though.

[wateret]

And IMHO about file names, I would suggest my_trace.chrome.json for chrome tracing, and my_trace.snpe.json for SNPE.

[YongseopKim]

Done