compiled printf support increases C source and ko module sizes a bit

Fri Nov 25 20:08:00 GMT 2011

On Fri, Nov 25, 2011 at 02:57:28PM +0100, Mark Wielaard wrote:
> I noticed the compiled printf support does bloat the generated src.c
> file a bit for things like:
> stap -e 'probe process("/bin/ls").function("*")
>         { printf("%s(%s)\n", probefunc(), $$parms) }'
> 
> It produces with stap 1.6 a 781K .c source file and a 1.2M .ko file.
>   and with stap git trunk a 1.1M .c source file and a 1.5M .ko file.

On irc Frank asked for a -t comparison. See attached.

It looks like the probe overhead is often hundreds of cycles lower.
But Pass 4 get more than a second slower.

Cheers,

Mark
-------------- next part --------------
Pass 1: parsed user script and 80 library script(s) using 200240virt/26432res/3028shr kb, in 120usr/10sys/131real ms.
Pass 2: analyzed script: 533 probe(s), 112 function(s), 1 embed(s), 0 global(s) using 207140virt/31956res/4012shr kb, in 40usr/0sys/48real ms.
Pass 3: translated to C into "/tmp/stapgeYY29/stap_32542.c" using 329104virt/32220res/4184shr kb, in 40usr/90sys/131real ms.
Pass 4: compiled C into "stap_32542.ko" in 3840usr/420sys/4249real ms.
Pass 5: starting run.
/dev/zero
main(argc=0x2 argv=0x7fffe5cc0a08)
set_program_name(argv0=0x7fffe5cc27ab)
initialize_exit_failure(status=0x2)
decode_switches(argv=? argc=?)
human_options(spec=0x0 opts=0x61a4d0 block_size=0x61a4d8)
humblock(options=? block_size=? spec=0x0)
default_block_size()
clone_quoting_options(o=0x0)
xmemdup(p=0x61ae20 s=0x38)
xmalloc(n=0x38)
get_quoting_style(o=0x246d050)
clone_quoting_options(o=0x0)
xmemdup(p=0x61ae20 s=0x38)
xmalloc(n=0x38)
set_char_quoting(o=0x246d090 c=0x3a i=0x1)
xnmalloc(s=? n=?)
xmalloc(n=0x4b00)
clear_files()
gobble_file(name=0x7fffe5cc27b3 type=0xa command_line_arg=0x1 dirname=0x4151ed inode=0x0)
stat(__statbuf=0x246d0e0 __path=0x7fffe5cc27b3)
lstat(__statbuf=0x246d0e0 __path=0x7fffe5cc27b3)
xstrdup(string=0x7fffe5cc27b3)
xmemdup(p=0x7fffe5cc27b3 s=0xa)
xmalloc(n=0xa)
sort_files()
xnmalloc(s=0x18 n=0x1)
xmalloc(n=0x18)
initialize_ordering_vector()
mpsort(base=0x2471c00 n=0x1 cmp=0x404130)
mpsort_with_tmp(base=0x2471c00 n=0x1 tmp=0x2471c08 cmp=0x404130)
extract_dirs_from_files(dirname=0x0 command_line_arg=0x1)
is_directory()
print_current_files()
print_file_name_and_frills(f=0x246d0d0 start_col=0x0)
set_normal_color()
print_name_with_quoting(f=0x246d0d0 symlink_target=0x0 stack=0x0 start_col=0x0)
quote_name(out=0x31e4b958c0 name=0x2471be0 options=0x246d050 width=0x0)
quotearg_buffer(buffer=0x7fffe5cbe080 buffersize=0x2000 arg=0x2471be0 argsize=0xffffffffffffffff o=0x246d050)
quotearg_buffer_restyled(buffer=0x7fffe5cbe080 buffersize=0x2000 arg=0x2471be0 argsize=0xffffffffffffffff quoting_style=0x0 flags=0x0 quote_these_too=0x246d058 left_quote=0x0 right_quote=0x0)
putchar_unlocked(__c=0xa)
print_dir(command_line_arg=? realname=? name=?)
close_stdout()
close_stream(stream=0x31e4b958c0)
ferror_unlocked(__stream=?)
close_stream(stream=0x31e4b959a0)
ferror_unlocked(__stream=?)
----- probe hit report: 
process("/bin/ls").function("print_current_files@/usr/src/debug/coreutils-8.5/src/ls.c:3458"), (<input>:1:1), hits: 1, cycles: 4348min/4348avg/4348max, from: process("/bin/ls").function("*")
process("/bin/ls").function("main@/usr/src/debug/coreutils-8.5/src/ls.c:1241"), (<input>:1:1), hits: 1, cycles: 19706min/19706avg/19706max, from: process("/bin/ls").function("*")
process("/bin/ls").function("quote_name@/usr/src/debug/coreutils-8.5/src/ls.c:3951"), (<input>:1:1), hits: 1, cycles: 9734min/9734avg/9734max, from: process("/bin/ls").function("*")
process("/bin/ls").function("extract_dirs_from_files@/usr/src/debug/coreutils-8.5/src/ls.c:3137"), (<input>:1:1), hits: 1, cycles: 8468min/8468avg/8468max, from: process("/bin/ls").function("*")
process("/bin/ls").function("sort_files@/usr/src/debug/coreutils-8.5/src/ls.c:3418"), (<input>:1:1), hits: 1, cycles: 4234min/4234avg/4234max, from: process("/bin/ls").function("*")
process("/bin/ls").function("print_file_name_and_frills@/usr/src/debug/coreutils-8.5/src/ls.c:4161"), (<input>:1:1), hits: 1, cycles: 7666min/7666avg/7666max, from: process("/bin/ls").function("*")
process("/bin/ls").function("clear_files@/usr/src/debug/coreutils-8.5/src/ls.c:2723"), (<input>:1:1), hits: 1, cycles: 4940min/4940avg/4940max, from: process("/bin/ls").function("*")
process("/bin/ls").function("set_normal_color@/usr/src/debug/coreutils-8.5/src/ls.c:1162"), (<input>:1:1), hits: 1, cycles: 3760min/3760avg/3760max, from: process("/bin/ls").function("*")
process("/bin/ls").function("print_name_with_quoting@/usr/src/debug/coreutils-8.5/src/ls.c:4111"), (<input>:1:1), hits: 1, cycles: 9420min/9420avg/9420max, from: process("/bin/ls").function("*")
process("/bin/ls").function("gobble_file@/usr/src/debug/coreutils-8.5/src/ls.c:2757"), (<input>:1:1), hits: 1, cycles: 12740min/12740avg/12740max, from: process("/bin/ls").function("*")
process("/bin/ls").function("initialize_ordering_vector@/usr/src/debug/coreutils-8.5/src/ls.c:3408"), (<input>:1:1), hits: 1, cycles: 4600min/4600avg/4600max, from: process("/bin/ls").function("*")
process("/bin/ls").function("stat@/usr/include/sys/stat.h:455"), (<input>:1:1), hits: 1, cycles: 9174min/9174avg/9174max, from: process("/bin/ls").function("*")
process("/bin/ls").function("xnmalloc@../lib/xalloc.h:122"), (<input>:1:1), hits: 1, cycles: 6194min/6194avg/6194max, from: process("/bin/ls").function("*")
process("/bin/ls").function("xnmalloc@../lib/xalloc.h:122"), (<input>:1:1), hits: 1, cycles: 5034min/5034avg/5034max, from: process("/bin/ls").function("*")
process("/bin/ls").function("decode_switches@/usr/src/debug/coreutils-8.5/src/ls.c:1521"), (<input>:1:1), hits: 1, cycles: 5854min/5854avg/5854max, from: process("/bin/ls").function("*")
process("/bin/ls").function("is_directory@/usr/src/debug/coreutils-8.5/src/ls.c:3070"), (<input>:1:1), hits: 1, cycles: 4100min/4100avg/4100max, from: process("/bin/ls").function("*")
process("/bin/ls").function("print_dir@/usr/src/debug/coreutils-8.5/src/ls.c:2483"), (<input>:1:1), hits: 1, cycles: 5448min/5448avg/5448max, from: process("/bin/ls").function("*")
process("/bin/ls").function("initialize_exit_failure@/usr/src/debug/coreutils-8.5/src/system.h:104"), (<input>:1:1), hits: 1, cycles: 8654min/8654avg/8654max, from: process("/bin/ls").function("*")
process("/bin/ls").function("putchar_unlocked@/usr/include/bits/stdio.h:106"), (<input>:1:1), hits: 1, cycles: 6420min/6420avg/6420max, from: process("/bin/ls").function("*")
process("/bin/ls").function("lstat@/usr/include/sys/stat.h:462"), (<input>:1:1), hits: 1, cycles: 8160min/8160avg/8160max, from: process("/bin/ls").function("*")
process("/bin/ls").function("set_program_name@/usr/src/debug/coreutils-8.5/lib/progname.c:39"), (<input>:1:1), hits: 1, cycles: 8388min/8388avg/8388max, from: process("/bin/ls").function("*")
process("/bin/ls").function("close_stdout@/usr/src/debug/coreutils-8.5/lib/closeout.c:107"), (<input>:1:1), hits: 1, cycles: 4066min/4066avg/4066max, from: process("/bin/ls").function("*")
process("/bin/ls").function("human_options@/usr/src/debug/coreutils-8.5/lib/human.c:462"), (<input>:1:1), hits: 1, cycles: 11408min/11408avg/11408max, from: process("/bin/ls").function("*")
process("/bin/ls").function("default_block_size@/usr/src/debug/coreutils-8.5/lib/human.c:406"), (<input>:1:1), hits: 1, cycles: 5020min/5020avg/5020max, from: process("/bin/ls").function("*")
process("/bin/ls").function("humblock@/usr/src/debug/coreutils-8.5/lib/human.c:412"), (<input>:1:1), hits: 1, cycles: 6920min/6920avg/6920max, from: process("/bin/ls").function("*")
process("/bin/ls").function("mpsort@/usr/src/debug/coreutils-8.5/lib/mpsort.c:153"), (<input>:1:1), hits: 1, cycles: 8800min/8800avg/8800max, from: process("/bin/ls").function("*")
process("/bin/ls").function("mpsort_with_tmp@/usr/src/debug/coreutils-8.5/lib/mpsort.c:86"), (<input>:1:1), hits: 1, cycles: 9594min/9594avg/9594max, from: process("/bin/ls").function("*")
process("/bin/ls").function("get_quoting_style@/usr/src/debug/coreutils-8.5/lib/quotearg.c:110"), (<input>:1:1), hits: 1, cycles: 6740min/6740avg/6740max, from: process("/bin/ls").function("*")
process("/bin/ls").function("clone_quoting_options@/usr/src/debug/coreutils-8.5/lib/quotearg.c:99"), (<input>:1:1), hits: 2, cycles: 5152min/5996avg/6840max, from: process("/bin/ls").function("*")
process("/bin/ls").function("quotearg_buffer@/usr/src/debug/coreutils-8.5/lib/quotearg.c:628"), (<input>:1:1), hits: 1, cycles: 13972min/13972avg/13972max, from: process("/bin/ls").function("*")
process("/bin/ls").function("set_char_quoting@/usr/src/debug/coreutils-8.5/lib/quotearg.c:129"), (<input>:1:1), hits: 1, cycles: 9174min/9174avg/9174max, from: process("/bin/ls").function("*")
process("/bin/ls").function("quotearg_buffer_restyled@/usr/src/debug/coreutils-8.5/lib/quotearg.c:204"), (<input>:1:1), hits: 1, cycles: 20026min/20026avg/20026max, from: process("/bin/ls").function("*")
process("/bin/ls").function("xstrdup@/usr/src/debug/coreutils-8.5/lib/xmalloc.c:115"), (<input>:1:1), hits: 1, cycles: 6580min/6580avg/6580max, from: process("/bin/ls").function("*")
process("/bin/ls").function("xmemdup@/usr/src/debug/coreutils-8.5/lib/xmalloc.c:107"), (<input>:1:1), hits: 3, cycles: 5934min/6938avg/8134max, from: process("/bin/ls").function("*")
process("/bin/ls").function("xmalloc@/usr/src/debug/coreutils-8.5/lib/xmalloc.c:43"), (<input>:1:1), hits: 5, cycles: 4368min/4913avg/5740max, from: process("/bin/ls").function("*")
process("/bin/ls").function("close_stream@/usr/src/debug/coreutils-8.5/lib/close-stream.c:56"), (<input>:1:1), hits: 2, cycles: 6920min/7236avg/7552max, from: process("/bin/ls").function("*")
process("/bin/ls").function("ferror_unlocked@/usr/include/bits/stdio.h:133"), (<input>:1:1), hits: 2, cycles: 4328min/4430avg/4532max, from: process("/bin/ls").function("*")
Pass 5: run completed in 10usr/70sys/342real ms.
Keeping temporary directory "/tmp/stapgeYY29"
-------------- next part --------------
Pass 1: parsed user script and 77 library script(s) using 196336virt/22764res/2960shr kb, in 110usr/0sys/108real ms.
Pass 2: analyzed script: 533 probe(s), 112 function(s), 0 embed(s), 0 global(s) using 203144virt/28208res/3940shr kb, in 40usr/10sys/48real ms.
Pass 3: translated to C into "/tmp/stapFbpjel/stap_830_src.c" using 325108virt/28472res/4204shr kb, in 50usr/80sys/133real ms.
Pass 4: compiled C into "stap_830.ko" in 5130usr/440sys/5447real ms.
Pass 5: starting run.
/dev/zero
main(argc=0x2 argv=0x7fffbf6077d8)
set_program_name(argv0=0x7fffbf609793)
initialize_exit_failure(status=0x2)
decode_switches(argv=? argc=?)
human_options(spec=0x0 opts=0x61a4d0 block_size=0x61a4d8)
humblock(options=? block_size=? spec=0x0)
default_block_size()
clone_quoting_options(o=0x0)
xmemdup(p=0x61ae20 s=0x38)
xmalloc(n=0x38)
get_quoting_style(o=0x19b2050)
clone_quoting_options(o=0x0)
xmemdup(p=0x61ae20 s=0x38)
xmalloc(n=0x38)
set_char_quoting(o=0x19b2090 c=0x3a i=0x1)
xnmalloc(s=? n=?)
xmalloc(n=0x4b00)
clear_files()
gobble_file(name=0x7fffbf60979b type=0xa command_line_arg=0x1 dirname=0x4151ed inode=0x0)
stat(__statbuf=0x19b20e0 __path=0x7fffbf60979b)
lstat(__statbuf=0x19b20e0 __path=0x7fffbf60979b)
xstrdup(string=0x7fffbf60979b)
xmemdup(p=0x7fffbf60979b s=0xa)
xmalloc(n=0xa)
sort_files()
xnmalloc(s=0x18 n=0x1)
xmalloc(n=0x18)
initialize_ordering_vector()
mpsort(base=0x19b6c00 n=0x1 cmp=0x404130)
mpsort_with_tmp(base=0x19b6c00 n=0x1 tmp=0x19b6c08 cmp=0x404130)
extract_dirs_from_files(dirname=0x0 command_line_arg=0x1)
is_directory()
print_current_files()
print_file_name_and_frills(f=0x19b20d0 start_col=0x0)
set_normal_color()
print_name_with_quoting(f=0x19b20d0 symlink_target=0x0 stack=0x0 start_col=0x0)
quote_name(out=0x31e4b958c0 name=0x19b6be0 options=0x19b2050 width=0x0)
quotearg_buffer(buffer=0x7fffbf604e50 buffersize=0x2000 arg=0x19b6be0 argsize=0xffffffffffffffff o=0x19b2050)
quotearg_buffer_restyled(buffer=0x7fffbf604e50 buffersize=0x2000 arg=0x19b6be0 argsize=0xffffffffffffffff quoting_style=0x0 flags=0x0 quote_these_too=0x19b2058 left_quote=0x0 right_quote=0x0)
putchar_unlocked(__c=0xa)
print_dir(command_line_arg=? realname=? name=?)
close_stdout()
close_stream(stream=0x31e4b958c0)
ferror_unlocked(__stream=?)
close_stream(stream=0x31e4b959a0)
ferror_unlocked(__stream=?)
----- probe hit report: 
process("/bin/ls").function("print_current_files@/usr/src/debug/coreutils-8.5/src/ls.c:3458"), (<input>:1:1), hits: 1, cycles: 3794min/3794avg/3794max, from: process("/bin/ls").function("*")
process("/bin/ls").function("main@/usr/src/debug/coreutils-8.5/src/ls.c:1241"), (<input>:1:1), hits: 1, cycles: 16340min/16340avg/16340max, from: process("/bin/ls").function("*")
process("/bin/ls").function("quote_name@/usr/src/debug/coreutils-8.5/src/ls.c:3951"), (<input>:1:1), hits: 1, cycles: 8714min/8714avg/8714max, from: process("/bin/ls").function("*")
process("/bin/ls").function("extract_dirs_from_files@/usr/src/debug/coreutils-8.5/src/ls.c:3137"), (<input>:1:1), hits: 1, cycles: 7354min/7354avg/7354max, from: process("/bin/ls").function("*")
process("/bin/ls").function("sort_files@/usr/src/debug/coreutils-8.5/src/ls.c:3418"), (<input>:1:1), hits: 1, cycles: 3394min/3394avg/3394max, from: process("/bin/ls").function("*")
process("/bin/ls").function("print_file_name_and_frills@/usr/src/debug/coreutils-8.5/src/ls.c:4161"), (<input>:1:1), hits: 1, cycles: 7420min/7420avg/7420max, from: process("/bin/ls").function("*")
process("/bin/ls").function("clear_files@/usr/src/debug/coreutils-8.5/src/ls.c:2723"), (<input>:1:1), hits: 1, cycles: 3906min/3906avg/3906max, from: process("/bin/ls").function("*")
process("/bin/ls").function("set_normal_color@/usr/src/debug/coreutils-8.5/src/ls.c:1162"), (<input>:1:1), hits: 1, cycles: 3420min/3420avg/3420max, from: process("/bin/ls").function("*")
process("/bin/ls").function("print_name_with_quoting@/usr/src/debug/coreutils-8.5/src/ls.c:4111"), (<input>:1:1), hits: 1, cycles: 8680min/8680avg/8680max, from: process("/bin/ls").function("*")
process("/bin/ls").function("gobble_file@/usr/src/debug/coreutils-8.5/src/ls.c:2757"), (<input>:1:1), hits: 1, cycles: 12108min/12108avg/12108max, from: process("/bin/ls").function("*")
process("/bin/ls").function("initialize_ordering_vector@/usr/src/debug/coreutils-8.5/src/ls.c:3408"), (<input>:1:1), hits: 1, cycles: 3700min/3700avg/3700max, from: process("/bin/ls").function("*")
process("/bin/ls").function("stat@/usr/include/sys/stat.h:455"), (<input>:1:1), hits: 1, cycles: 8548min/8548avg/8548max, from: process("/bin/ls").function("*")
process("/bin/ls").function("xnmalloc@../lib/xalloc.h:122"), (<input>:1:1), hits: 1, cycles: 6088min/6088avg/6088max, from: process("/bin/ls").function("*")
process("/bin/ls").function("xnmalloc@../lib/xalloc.h:122"), (<input>:1:1), hits: 1, cycles: 4434min/4434avg/4434max, from: process("/bin/ls").function("*")
process("/bin/ls").function("decode_switches@/usr/src/debug/coreutils-8.5/src/ls.c:1521"), (<input>:1:1), hits: 1, cycles: 5066min/5066avg/5066max, from: process("/bin/ls").function("*")
process("/bin/ls").function("is_directory@/usr/src/debug/coreutils-8.5/src/ls.c:3070"), (<input>:1:1), hits: 1, cycles: 3240min/3240avg/3240max, from: process("/bin/ls").function("*")
process("/bin/ls").function("print_dir@/usr/src/debug/coreutils-8.5/src/ls.c:2483"), (<input>:1:1), hits: 1, cycles: 4954min/4954avg/4954max, from: process("/bin/ls").function("*")
process("/bin/ls").function("initialize_exit_failure@/usr/src/debug/coreutils-8.5/src/system.h:104"), (<input>:1:1), hits: 1, cycles: 7206min/7206avg/7206max, from: process("/bin/ls").function("*")
process("/bin/ls").function("putchar_unlocked@/usr/include/bits/stdio.h:106"), (<input>:1:1), hits: 1, cycles: 5592min/5592avg/5592max, from: process("/bin/ls").function("*")
process("/bin/ls").function("lstat@/usr/include/sys/stat.h:462"), (<input>:1:1), hits: 1, cycles: 7088min/7088avg/7088max, from: process("/bin/ls").function("*")
process("/bin/ls").function("set_program_name@/usr/src/debug/coreutils-8.5/lib/progname.c:39"), (<input>:1:1), hits: 1, cycles: 8006min/8006avg/8006max, from: process("/bin/ls").function("*")
process("/bin/ls").function("close_stdout@/usr/src/debug/coreutils-8.5/lib/closeout.c:107"), (<input>:1:1), hits: 1, cycles: 3586min/3586avg/3586max, from: process("/bin/ls").function("*")
process("/bin/ls").function("human_options@/usr/src/debug/coreutils-8.5/lib/human.c:462"), (<input>:1:1), hits: 1, cycles: 10266min/10266avg/10266max, from: process("/bin/ls").function("*")
process("/bin/ls").function("default_block_size@/usr/src/debug/coreutils-8.5/lib/human.c:406"), (<input>:1:1), hits: 1, cycles: 3974min/3974avg/3974max, from: process("/bin/ls").function("*")
process("/bin/ls").function("humblock@/usr/src/debug/coreutils-8.5/lib/human.c:412"), (<input>:1:1), hits: 1, cycles: 6094min/6094avg/6094max, from: process("/bin/ls").function("*")
process("/bin/ls").function("mpsort@/usr/src/debug/coreutils-8.5/lib/mpsort.c:153"), (<input>:1:1), hits: 1, cycles: 8520min/8520avg/8520max, from: process("/bin/ls").function("*")
process("/bin/ls").function("mpsort_with_tmp@/usr/src/debug/coreutils-8.5/lib/mpsort.c:86"), (<input>:1:1), hits: 1, cycles: 8720min/8720avg/8720max, from: process("/bin/ls").function("*")
process("/bin/ls").function("get_quoting_style@/usr/src/debug/coreutils-8.5/lib/quotearg.c:110"), (<input>:1:1), hits: 1, cycles: 5426min/5426avg/5426max, from: process("/bin/ls").function("*")
process("/bin/ls").function("clone_quoting_options@/usr/src/debug/coreutils-8.5/lib/quotearg.c:99"), (<input>:1:1), hits: 2, cycles: 4512min/5352avg/6192max, from: process("/bin/ls").function("*")
process("/bin/ls").function("quotearg_buffer@/usr/src/debug/coreutils-8.5/lib/quotearg.c:628"), (<input>:1:1), hits: 1, cycles: 12428min/12428avg/12428max, from: process("/bin/ls").function("*")
process("/bin/ls").function("set_char_quoting@/usr/src/debug/coreutils-8.5/lib/quotearg.c:129"), (<input>:1:1), hits: 1, cycles: 8226min/8226avg/8226max, from: process("/bin/ls").function("*")
process("/bin/ls").function("quotearg_buffer_restyled@/usr/src/debug/coreutils-8.5/lib/quotearg.c:204"), (<input>:1:1), hits: 1, cycles: 17354min/17354avg/17354max, from: process("/bin/ls").function("*")
process("/bin/ls").function("xstrdup@/usr/src/debug/coreutils-8.5/lib/xmalloc.c:115"), (<input>:1:1), hits: 1, cycles: 6294min/6294avg/6294max, from: process("/bin/ls").function("*")
process("/bin/ls").function("xmemdup@/usr/src/debug/coreutils-8.5/lib/xmalloc.c:107"), (<input>:1:1), hits: 3, cycles: 4760min/6164avg/7720max, from: process("/bin/ls").function("*")
process("/bin/ls").function("xmalloc@/usr/src/debug/coreutils-8.5/lib/xmalloc.c:43"), (<input>:1:1), hits: 5, cycles: 3688min/4168avg/5408max, from: process("/bin/ls").function("*")
process("/bin/ls").function("close_stream@/usr/src/debug/coreutils-8.5/lib/close-stream.c:56"), (<input>:1:1), hits: 2, cycles: 6334min/6367avg/6400max, from: process("/bin/ls").function("*")
process("/bin/ls").function("ferror_unlocked@/usr/include/bits/stdio.h:133"), (<input>:1:1), hits: 2, cycles: 3834min/3997avg/4160max, from: process("/bin/ls").function("*")
Pass 5: run completed in 10usr/80sys/342real ms.
Keeping temporary directory "/tmp/stapFbpjel"