- Note: This is a continuation from Part 3 [1].
[1] Experiments with libarchive read blocking: Part 3
- Modify
cwrap.pl
to report the stack pointer on every log line. - Modify
./doit.sh
to runexample3.c
with two archives, and show the SHA256 sums of the extracted files. - Rebuild
example3.c
and run via./doit.sh
. - We can see that the largest amount of stack space used is about 1,280 bytes.
- At the deepest stack, the indentation of the log line shows that the call-tree is about 13 functions deep. Although obviously each function uses a variable amount of stack space during its invocation.
- The deepest stack also happens to be one of the callback invocations for each archive file.
- We can also see that at each callback the stack used varies a lot. So something to keep in mind: A more complex archive might increase the stack size? Something to investigate...
- Note: The cwrap instrumentation itself is responsible for part of the stack size used, because the function depth doubles.
$ ./doit.sh
...
11d4fec99890b26d8ee8ebb9710ff36b665c5fb4653d43de2ea86a3d52dc7b3b ./.libs/libarchive_test_1a.a
295ef327b417e4118d0329ef707d360b0bc40ce12be336d2ce006422dd593429 ./.libs/libarchive_test_1b.a
295ef327b417e4118d0329ef707d360b0bc40ce12be336d2ce006422dd593429 ./.libs/libarchive_test_2a.a
11d4fec99890b26d8ee8ebb9710ff36b665c5fb4653d43de2ea86a3d52dc7b3b ./.libs/libarchive_test_2b.a
$ head -20 example3.cwrap.out
T25606 C0 SP +0 0.000000s + archive_read_new() {
T25606 C0 SP -64 0.000292s + archive_entry_new2() {} = ? // #1
T25606 C0 SP +0 0.000380s } = ? // archive_read_new() #1
T25606 C0 SP +0 0.000415s + archive_read_support_format_all() {
T25606 C0 SP -80 0.000428s + __archive_check_magic() {} = 0 // #1
T25606 C0 SP -48 0.000478s + archive_read_support_format_ar() {
T25606 C0 SP -144 0.000490s + __archive_check_magic() {} = 0 // #2
T25606 C0 SP -208 0.000540s + __archive_read_register_format() {
T25606 C0 SP -384 0.000552s + __archive_check_magic() {} = 0 // #3
T25606 C0 SP -208 0.000602s } = 0 // __archive_read_register_format() #1
T25606 C0 SP -48 0.000801s } = 0 // archive_read_support_format_ar() #1
T25606 C0 SP -48 0.000879s + archive_read_support_format_cpio() {
T25606 C0 SP -144 0.000914s + __archive_check_magic() {} = 0 // #4
T25606 C0 SP -208 0.000971s + __archive_read_register_format() {
T25606 C0 SP -384 0.000983s + __archive_check_magic() {} = 0 // #5
T25606 C0 SP -208 0.001032s } = 0 // __archive_read_register_format() #2
T25606 C0 SP -48 0.001063s } = 0 // archive_read_support_format_cpio() #1
T25606 C0 SP -48 0.001093s + archive_read_support_format_empty() {
T25606 C0 SP -128 0.001105s + __archive_check_magic() {} = 0 // #6
T25606 C0 SP -192 0.001154s + __archive_read_register_format() {
$ cat example3.cwrap.out | perl -lane '$lines++; if(m~SP\s*[\-|+]*(\d+)~){ $sp=$1; $sp_hi=$sp if($sp > $sp_hi); } sub END{ printf qq[- sp_hi=%d lines=%d\n], $sp_hi, $lines; }'
- sp_hi=1280 lines=13952
$ cat example3.cwrap.out | egrep "SP-1280"
T25606 C0 SP -1280 0.438052s - libarchive_read_callback(0=id) {} = 0=bytes_available
T25606 C0 SP -1280 0.580512s - libarchive_read_callback(1=id) {} = 0=bytes_available
$ cat example3.cwrap.out | egrep "libarchive_read_callback.*bytes_available"
T25606 C0 SP -576 0.102593s - libarchive_read_callback(0=id) {} = 7=bytes_available
T25606 C0 SP -576 0.102968s - libarchive_read_callback(0=id) {} = 7=bytes_available
T25606 C0 SP -800 0.109330s - libarchive_read_callback(0=id) {} = 7=bytes_available
T25606 C0 SP -800 0.109868s - libarchive_read_callback(0=id) {} = 262,144=bytes_available
T25606 C0 SP -576 0.222140s - libarchive_read_callback(1=id) {} = 7=bytes_available
T25606 C0 SP -576 0.222447s - libarchive_read_callback(1=id) {} = 7=bytes_available
T25606 C0 SP -800 0.228260s - libarchive_read_callback(1=id) {} = 7=bytes_available
T25606 C0 SP -800 0.228802s - libarchive_read_callback(1=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.275702s - libarchive_read_callback(0=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.303442s - libarchive_read_callback(0=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.326784s - libarchive_read_callback(0=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.350137s - libarchive_read_callback(0=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.375164s - libarchive_read_callback(0=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.399960s - libarchive_read_callback(0=id) {} = 116,967=bytes_available
T25606 C0 SP -1280 0.438052s - libarchive_read_callback(0=id) {} = 0=bytes_available
T25606 C0 SP -1056 0.466527s - libarchive_read_callback(1=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.487312s - libarchive_read_callback(1=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.505807s - libarchive_read_callback(1=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.526057s - libarchive_read_callback(1=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.548620s - libarchive_read_callback(1=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.571182s - libarchive_read_callback(1=id) {} = 116,704=bytes_available
T25606 C0 SP -1280 0.580512s - libarchive_read_callback(1=id) {} = 0=bytes_available
- Note: The
id
below is the archive number of either 0 or 1 and not the coroutine number. - Note: The
Cn
below is the coroutine number between 0 and 2 and not the archive number. - Note: coroutine 0 represents the regular program flow, while coroutines 1 and 2 are created for reading archives 0 and 1.
$ cp cogo-3-dummy-libarchive.c cor.c
$ cp example3.c example4.c
$ cp doit.sh doit4.sh
$ touch cor.h
$ # hack cor.[ch] to provide our home-grown coroutines
$ # hack example4 to work with our home-grown coroutines; business logic alternates between archives and libarchive_read_callback() functions
$ # hack cwrap to work with our home-grown coroutines
$ # hack doit4.sh to work with example4.c
$ ./doit4.sh
make all-am
make[1]: Entering directory '/home/simon/20191016-libarchive/libarchive'
make[1]: Leaving directory '/home/simon/20191016-libarchive/libarchive'
Fri Nov 8 18:18:20 2019 0.099997 cwrap: gcc .. > cor.o.cwrap.cc.out; 8 functions, 1 warnings
Fri Nov 8 18:18:20 2019 0.189195 cwrap: gcc .. > example4.o.cwrap.cc.out; 4 functions, 3 warnings
Fri Nov 8 18:18:20 2019 0.241950 cwrap: gcc .. > .cwrap.cc.out; 121 objects , 0 libs
0=id - main_n_coroutine(1) {} // ready to unpack!
1=id - main_n_coroutine(2) {} // ready to unpack!
- main_0_coroutine() {}
0=id - for archive file 0: read off disk, and archive_read_open()
0=id - attempting to open: test_1.tar.gz
0=id - read 1,689,852 bytes into id_buff_archive[0]
0=id - archive_read_new() {}
0=id - archive_read_open() {
1=id - for archive file 1: read off disk, and archive_read_open()
1=id - attempting to open: test_2.tar.gz
1=id - read 1,689,589 bytes into id_buff_archive[1]
1=id - archive_read_new() {}
1=id - archive_read_open() {
0=id - libarchive_read_callback() {} = 7=bytes_available
1=id - libarchive_read_callback() {} = 7=bytes_available
0=id - libarchive_read_callback() {} = 7=bytes_available
1=id - libarchive_read_callback() {} = 7=bytes_available
0=id - libarchive_read_callback() {} = 7=bytes_available
1=id - libarchive_read_callback() {} = 7=bytes_available
0=id - libarchive_read_callback() {} = 262,144=bytes_available
0=id } = ARCHIVE_OK
0=id - for archive file 0: archive_read_next_header() and archive_read_extract()
0=id - archive_read_next_header() {} = ARCHIVE_OK
0=id - archive_entry_pathname(entry) {} = .libs/libarchive_test_1a.a // file to extract
0=id - archive_read_extract() {
1=id - libarchive_read_callback() {} = 262,144=bytes_available
1=id } = ARCHIVE_OK
1=id - for archive file 1: archive_read_next_header() and archive_read_extract()
1=id - archive_read_next_header() {} = ARCHIVE_OK
1=id - archive_entry_pathname(entry) {} = .libs/libarchive_test_2a.a // file to extract
1=id - archive_read_extract() {
1=id } = ARCHIVE_OK
1=id - archive_read_next_header() {} = ARCHIVE_OK
1=id - archive_entry_pathname(entry) {} = .libs/libarchive_test_2b.a // file to extract
1=id - archive_read_extract() {
0=id - libarchive_read_callback() {} = 262,144=bytes_available
1=id - libarchive_read_callback() {} = 262,144=bytes_available
0=id - libarchive_read_callback() {} = 262,144=bytes_available
1=id - libarchive_read_callback() {} = 262,144=bytes_available
0=id - libarchive_read_callback() {} = 262,144=bytes_available
1=id - libarchive_read_callback() {} = 262,144=bytes_available
0=id - libarchive_read_callback() {} = 262,144=bytes_available
1=id - libarchive_read_callback() {} = 262,144=bytes_available
0=id - libarchive_read_callback() {} = 262,144=bytes_available
1=id - libarchive_read_callback() {} = 262,144=bytes_available
0=id - libarchive_read_callback() {} = 116,967=bytes_available
0=id } = ARCHIVE_OK
0=id - archive_read_next_header() {} = ARCHIVE_OK
0=id - archive_entry_pathname(entry) {} = .libs/libarchive_test_1b.a // file to extract
0=id - archive_read_extract() {
1=id - libarchive_read_callback() {} = 116,704=bytes_available
0=id - libarchive_read_callback() {} = 0=bytes_available
0=id } = ARCHIVE_OK
0=id - archive_read_next_header() {} = ARCHIVE_EOF
0=id - for archive file 0: archive_read_close() and archive_read_free()
0=id - archive_read_close() {}
0=id - archive_read_free() {}
0=id - main_n_coroutine(1) {} // ready to unpack!
1=id - libarchive_read_callback() {} = 0=bytes_available
1=id } = ARCHIVE_OK
1=id - archive_read_next_header() {} = ARCHIVE_EOF
1=id - for archive file 1: archive_read_close() and archive_read_free()
1=id - archive_read_close() {}
1=id - archive_read_free() {}
1=id - main_n_coroutine(2) {} // ready to unpack!
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
53.44 0.000799 0 14618 write
44.35 0.000663 95 7 read
2.21 0.000033 0 14359 gettid
0.00 0.000000 0 14 open
0.00 0.000000 0 13 close
0.00 0.000000 0 9 fstat
0.00 0.000000 0 18 mmap
0.00 0.000000 0 12 mprotect
0.00 0.000000 0 1 munmap
0.00 0.000000 0 9 brk
0.00 0.000000 0 7 7 access
0.00 0.000000 0 1 execve
0.00 0.000000 0 4 fcntl
0.00 0.000000 0 12 umask
0.00 0.000000 0 1 getrlimit
0.00 0.000000 0 2 geteuid
0.00 0.000000 0 1 arch_prctl
0.00 0.000000 0 4 utimensat
------ ----------- ----------- --------- --------- ----------------
100.00 0.001495 29092 7 total
T28688 C2 SP-20864 0.519121s + archive_wstring_free() {} // #85
T28688 C2 SP-20864 0.519162s + archive_string_free() {} // #301
T28688 C2 SP-20864 0.519186s + archive_string_free() {} // #302
T28688 C2 SP-20864 0.519218s + archive_string_free() {} // #303
T28688 C2 SP-20784 0.519243s } // archive_mstring_clean() #81
T28688 C2 SP-20816 0.519269s + archive_mstring_clean() {
T28688 C2 SP-20864 0.519278s + archive_wstring_free() {} // #86
T28688 C2 SP-20864 0.519319s + archive_string_free() {} // #304
T28688 C2 SP-20864 0.519344s + archive_string_free() {} // #305
T28688 C2 SP-20864 0.519369s + archive_string_free() {} // #306
T28688 C2 SP-20784 0.519395s } // archive_mstring_clean() #82
T28688 C2 SP-20816 0.519420s + archive_mstring_clean() {
T28688 C2 SP-20864 0.519429s + archive_wstring_free() {} // #87
T28688 C2 SP-20864 0.519470s + archive_string_free() {} // #307
T28688 C2 SP-20864 0.519495s + archive_string_free() {} // #308
T28688 C2 SP-20864 0.519521s + archive_string_free() {} // #309
T28688 C2 SP-20784 0.519546s } // archive_mstring_clean() #83
T28688 C2 SP-20816 0.519571s + archive_mstring_clean() {
T28688 C2 SP-20864 0.519580s + archive_wstring_free() {} // #88
T28688 C2 SP-20864 0.519621s + archive_string_free() {} // #310
T28688 C2 SP-20864 0.519646s + archive_string_free() {} // #311
T28688 C2 SP-20864 0.519671s + archive_string_free() {} // #312
T28688 C2 SP-20784 0.519697s } // archive_mstring_clean() #84
T28688 C2 SP-20832 0.519722s + archive_entry_copy_mac_metadata() {} // #16
T28688 C2 SP-20816 0.519747s + archive_acl_clear() {} // #16
T28688 C2 SP-20816 0.519773s + archive_entry_xattr_clear() {} // #12
T28688 C2 SP-20816 0.519798s + archive_entry_sparse_clear() {} // #12
T28688 C2 SP-20768 0.519823s } = ? // archive_entry_clear() #14
T28688 C2 SP-20688 0.519849s } // archive_entry_free() #8
T28688 C2 SP-20720 0.519874s + __archive_clean() {
T28688 C2 SP-20768 0.519884s + archive_string_conversion_free() {} // #4
T28688 C2 SP-20720 0.519933s } = 0 // __archive_clean() #4
T28688 C2 SP-20640 0.519980s } = 0 // _archive_read_free() #2
T28688 C2 SP-20608 0.520006s } = 0 // archive_free() #4
T28688 C2 SP-20576 0.520032s } = 0 // archive_read_free() #2
T28688 C2 SP-20592 0.520068s + cor_switch() {
T28688 C2 SP-20672 0.520078s + cor_switch_internal() {
T28688 C2 SP-20720 0.520104s - switch: 2 -> 0 // setjmp(2) for jump point b
T28688 C2 SP-20720 0.520145s - switch: 2 -> 0 // longjmp(0)
... voodoo ...
T28688 C0 SP-30624 0.520171s } // cor_switch_internal() #50
T28688 C0 SP-30576 0.520196s - continued via jump point b
T28688 C0 SP-30624 0.520222s + cor_sanity_check() {} // #53; co_stack_addr_main@-30,672 end1@-0 end2@-8,388,608
T28688 C0 SP-30544 0.520248s } // cor_switch() #50
T28688 C0 SP-30432 0.520273s } // main_0_coroutine() #1
T28688 C0 SP-30432 0.520299s - coroutine 0 exiting; process shutting down shortly?
T28688 C0 SP -256 0.520324s } // cor_launch_internal() #3
T28688 C0 SP -144 0.520350s } // cor_launch() #3
T28688 C0 SP +0 0.520376s } // cor_launch_all() #1
T28688 C0 SP +80 0.520401s - coroutines done!
11d4fec99890b26d8ee8ebb9710ff36b665c5fb4653d43de2ea86a3d52dc7b3b ./.libs/libarchive_test_1a.a
295ef327b417e4118d0329ef707d360b0bc40ce12be336d2ce006422dd593429 ./.libs/libarchive_test_1b.a
295ef327b417e4118d0329ef707d360b0bc40ce12be336d2ce006422dd593429 ./.libs/libarchive_test_2a.a
11d4fec99890b26d8ee8ebb9710ff36b665c5fb4653d43de2ea86a3d52dc7b3b ./.libs/libarchive_test_2b.a
$ cat example4.cwrap.out | wc -l
14413
- Below we can see that
example3.c
output shows blocks of processing due to the lack of async functionality. - Below we can see that
example4.c
output shows interleaving processing due to the new async-like functionality.
$ cat example3.cwrap.out | egrep "libarchive_read_callback.*bytes_available"
T25606 C0 SP -576 0.102593s - libarchive_read_callback(0=id) {} = 7=bytes_available
T25606 C0 SP -576 0.102968s - libarchive_read_callback(0=id) {} = 7=bytes_available
T25606 C0 SP -800 0.109330s - libarchive_read_callback(0=id) {} = 7=bytes_available
T25606 C0 SP -800 0.109868s - libarchive_read_callback(0=id) {} = 262,144=bytes_available
T25606 C0 SP -576 0.222140s - libarchive_read_callback(1=id) {} = 7=bytes_available
T25606 C0 SP -576 0.222447s - libarchive_read_callback(1=id) {} = 7=bytes_available
T25606 C0 SP -800 0.228260s - libarchive_read_callback(1=id) {} = 7=bytes_available
T25606 C0 SP -800 0.228802s - libarchive_read_callback(1=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.275702s - libarchive_read_callback(0=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.303442s - libarchive_read_callback(0=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.326784s - libarchive_read_callback(0=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.350137s - libarchive_read_callback(0=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.375164s - libarchive_read_callback(0=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.399960s - libarchive_read_callback(0=id) {} = 116,967=bytes_available
T25606 C0 SP -1280 0.438052s - libarchive_read_callback(0=id) {} = 0=bytes_available
T25606 C0 SP -1056 0.466527s - libarchive_read_callback(1=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.487312s - libarchive_read_callback(1=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.505807s - libarchive_read_callback(1=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.526057s - libarchive_read_callback(1=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.548620s - libarchive_read_callback(1=id) {} = 262,144=bytes_available
T25606 C0 SP -1056 0.571182s - libarchive_read_callback(1=id) {} = 116,704=bytes_available
T25606 C0 SP -1280 0.580512s - libarchive_read_callback(1=id) {} = 0=bytes_available
$ cat example4.cwrap.out | egrep "libarchive_read_callback.*bytes_available"
T28688 C1 SP-11120 0.142435s } = ? // libarchive_read_callback() #2; bytes_available=7
T28688 C2 SP-21120 0.143123s } = ? // libarchive_read_callback() #3; bytes_available=7
T28688 C1 SP-11120 0.143815s } = ? // libarchive_read_callback() #4; bytes_available=7
T28688 C2 SP-21120 0.147809s } = ? // libarchive_read_callback() #5; bytes_available=7
T28688 C1 SP-11344 0.151809s } = ? // libarchive_read_callback() #6; bytes_available=7
T28688 C2 SP-21344 0.152651s } = ? // libarchive_read_callback() #7; bytes_available=7
T28688 C1 SP-11344 0.153486s } = ? // libarchive_read_callback() #8; bytes_available=262,144
T28688 C2 SP-21344 0.187212s } = ? // libarchive_read_callback() #9; bytes_available=262,144
T28688 C1 SP-11600 0.236439s } = ? // libarchive_read_callback() #10; bytes_available=262,144
T28688 C2 SP-21600 0.260115s } = ? // libarchive_read_callback() #11; bytes_available=262,144
T28688 C1 SP-11600 0.285268s } = ? // libarchive_read_callback() #12; bytes_available=262,144
T28688 C2 SP-21600 0.306599s } = ? // libarchive_read_callback() #13; bytes_available=262,144
T28688 C1 SP-11600 0.325048s } = ? // libarchive_read_callback() #14; bytes_available=262,144
T28688 C2 SP-21600 0.347720s } = ? // libarchive_read_callback() #15; bytes_available=262,144
T28688 C1 SP-11600 0.369507s } = ? // libarchive_read_callback() #16; bytes_available=262,144
T28688 C2 SP-21600 0.392095s } = ? // libarchive_read_callback() #17; bytes_available=262,144
T28688 C1 SP-11600 0.416115s } = ? // libarchive_read_callback() #18; bytes_available=262,144
T28688 C2 SP-21600 0.438947s } = ? // libarchive_read_callback() #19; bytes_available=262,144
T28688 C1 SP-11600 0.461652s } = ? // libarchive_read_callback() #20; bytes_available=116,967
T28688 C2 SP-21600 0.486657s } = ? // libarchive_read_callback() #21; bytes_available=116,704
T28688 C1 SP-11824 0.497856s } = ? // libarchive_read_callback() #22; bytes_available=0
T28688 C2 SP-21824 0.509564s } = ? // libarchive_read_callback() #22; bytes_available=0
- Below we can see that the extracted files have the same SHA256 sums with and without coroutines.
$ ./doit.sh
...
11d4fec99890b26d8ee8ebb9710ff36b665c5fb4653d43de2ea86a3d52dc7b3b ./.libs/libarchive_test_1a.a
295ef327b417e4118d0329ef707d360b0bc40ce12be336d2ce006422dd593429 ./.libs/libarchive_test_1b.a
295ef327b417e4118d0329ef707d360b0bc40ce12be336d2ce006422dd593429 ./.libs/libarchive_test_2a.a
11d4fec99890b26d8ee8ebb9710ff36b665c5fb4653d43de2ea86a3d52dc7b3b ./.libs/libarchive_test_2b.a
$ ./doit4.sh
...
11d4fec99890b26d8ee8ebb9710ff36b665c5fb4653d43de2ea86a3d52dc7b3b ./.libs/libarchive_test_1a.a
295ef327b417e4118d0329ef707d360b0bc40ce12be336d2ce006422dd593429 ./.libs/libarchive_test_1b.a
295ef327b417e4118d0329ef707d360b0bc40ce12be336d2ce006422dd593429 ./.libs/libarchive_test_2a.a
11d4fec99890b26d8ee8ebb9710ff36b665c5fb4653d43de2ea86a3d52dc7b3b ./.libs/libarchive_test_2b.a