no arguments and return value printed for program's local function (already compiled with debugging symbol -g3)

[realyukii]

compiled with:

gcc -DENABLE_LOG=false -Wmaybe-uninitialized -Wall -Wextra -g3 -finstrument-functions  -c gwproxy.c -o build/gwproxy.o
gcc -DENABLE_LOG=false -Wmaybe-uninitialized -Wall -Wextra -g3 -finstrument-functions  -c gwsocks5lib.c -o build/gwsocks5lib.o
gcc -DENABLE_LOG=false -Wmaybe-uninitialized -Wall -Wextra -g3 -finstrument-functions  -c linux.c -o build/linux.o
gcc   build/gwproxy.o build/gwsocks5lib.o build/linux.o build/general.o   -o build/gwproxy

and running the program with uftrace with:

uftrace live --no-pager -a -- build/gwproxy -s -b [::]:1080 -T 1 -w 60
# DURATION     TID      FUNCTION
            [ 667708] | main() {
            [ 667708] |   handle_cmdline() {
   0.841 us [ 667708] |     memset(0x7ffc22dccc90, 0, 48);
 136.134 us [ 667708] |     getopt(8, 0x7ffc22dcd068, "hw:b:t:T:f:sn:g:j:k:l:p:y:") = 115;
   0.280 us [ 667708] |     getopt(8, 0x7ffc22dcd068, "hw:b:t:T:f:sn:g:j:k:l:p:y:") = 98;
   0.130 us [ 667708] |     getopt(8, 0x7ffc22dcd068, "hw:b:t:T:f:sn:g:j:k:l:p:y:") = 84;
   0.090 us [ 667708] |     getopt(8, 0x7ffc22dcd068, "hw:b:t:T:f:sn:g:j:k:l:p:y:") = 119;
   0.101 us [ 667708] |     getopt(8, 0x7ffc22dcd068, "hw:b:t:T:f:sn:g:j:k:l:p:y:") = -1;
   0.100 us [ 667708] |     set_buffer_sizes();
   0.030 us [ 667708] |     set_intval();
            [ 667708] |     set_intval() {
   0.421 us [ 667708] |       atoi("1") = 1;
   0.711 us [ 667708] |     } /* set_intval */
            [ 667708] |     set_intval() {
   0.091 us [ 667708] |       atoi("60") = 60;
   0.241 us [ 667708] |     } /* set_intval */
   0.120 us [ 667708] |     memset(0x7ffc22dcce28, 0, 128);
            [ 667708] |     init_addr() {
   0.401 us [ 667708] |       strlen("[::]:1080") = 9;
   0.431 us [ 667708] |       strncpy(0x7ffc22dccbd0, "[::]:1080", 10);
   0.090 us [ 667708] |       atoi("1080") = 1080;
   0.380 us [ 667708] |       htons();
   2.696 us [ 667708] |       inet_pton(AF_INET6, "::", 0x7ffc22dcce30) = 1;
   4.949 us [ 667708] |     } /* init_addr */
 147.175 us [ 667708] |   } /* handle_cmdline */
            [ 667708] |   init_pctx() {
   1.713 us [ 667708] |     eventfd();
   0.291 us [ 667708] |     malloc(64) = 0x558967678bf0;
            [ 667708] |     socks5_init() {
   0.090 us [ 667708] |       malloc(56) = 0x558967700420;
   0.271 us [ 667708] |     } /* socks5_init */
   2.886 us [ 667708] |   } /* init_pctx */
   0.611 us [ 667708] |   sigaction(SIGTERM, 0x7ffc22dccd40, 0) = 0;
   0.261 us [ 667708] |   sigaction(SIGINT, 0x7ffc22dccd40, 0) = 0;
            [ 667708] |   setfdlimit() {
   0.732 us [ 667708] |     getrlimit();
   0.691 us [ 667708] |     setrlimit();
   0.251 us [ 667708] |     __errno_location();
   2.094 us [ 667708] |   } /* setfdlimit */
            [ 667708] |   spawn_threads() {
            [ 667708] |     init_tctx() {
            [ 667708] |       init_container() {
   1.663 us [ 667708] |         calloc(100, 8) = 0x5589676aaa80;
   1.973 us [ 667708] |       } /* init_container */
            [ 667708] |       prepare_tcp_serv() {
   7.113 us [ 667708] |         socket(AF_INET6, SOCK_STREAM, 0) = 7;
   1.472 us [ 667708] |         setsockopt();
   0.320 us [ 667708] |         setsockopt();
   3.437 us [ 667708] |         bind(7, 0x7ffc22dcce28, 128) = 0;
   2.675 us [ 667708] |         listen();
   1.563 us [ 667708] |         epoll_create(1) = 8;
            [ 667708] |         register_events() {
            [ 667708] |           custom_epoll_ctl() {
   2.004 us [ 667708] |             epoll_ctl(8, EPOLL_CTL_ADD, 7, 0x7ffc22dccb9c) = 0;
   2.294 us [ 667708] |           } /* custom_epoll_ctl */
   2.384 us [ 667708] |         } /* register_events */
            [ 667708] |         register_events() {
            [ 667708] |           custom_epoll_ctl() {
   0.792 us [ 667708] |             epoll_ctl(8, EPOLL_CTL_ADD, 6, 0x7ffc22dccb9c) = 0;
   0.952 us [ 667708] |           } /* custom_epoll_ctl */
   1.032 us [ 667708] |         } /* register_events */
  21.249 us [ 667708] |       } /* prepare_tcp_serv */
  23.574 us [ 667708] |     } /* init_tctx */
            [ 667708] |     start_tcp_serv() {
            [ 667708] |       epoll_wait(8, 0x7ffc22dcb470, 512, -1) {
   6.234  s [ 667708] |         /* linux:schedule */
            [ 667708] |         signal_handler() {
   8.456 us [ 667708] |           write(6, 0x7ffc22dca7e0, 8) = 8;
  13.045 us [ 667708] |         } /* signal_handler */
   6.234  s [ 667708] |       } = -1; /* epoll_wait */
   0.241 us [ 667708] |       __errno_location();
            [ 667708] |       cleanup_tctx() {
  22.512 us [ 667708] |         close(7) = 0;
   3.677 us [ 667708] |         close(8) = 0;
   1.823 us [ 667708] |         free(0x5589676aaa80);
  30.426 us [ 667708] |       } /* cleanup_tctx */
   6.234  s [ 667708] |     } /* start_tcp_serv */
   6.234  s [ 667708] |   } /* spawn_threads */
            [ 667708] |   cleanup_resources() {
   0.101 us [ 667708] |     join_threads();
            [ 667708] |     socks5_free_ctx() {
   0.240 us [ 667708] |       free(0x558967700420);
   0.672 us [ 667708] |     } /* socks5_free_ctx */
   0.110 us [ 667708] |     free(0x558967678bf0);
   2.966 us [ 667708] |     close(6) = 0;
   4.949 us [ 667708] |   } /* cleanup_resources */
   6.234  s [ 667708] | } /* main */

it print the arguments and return value for libc-related function, but the local function is not printed, is there a way to also print the arugments and return value for local function? I already set -a/--auto-args option

[realyukii]

oh, problem solved, it seems it must compiled with -pg flag instead of finstrument-functions :)

# DURATION     TID      FUNCTION
            [ 668501] | main(8, 0x7ffc30844f78) {
            [ 668501] |   handle_cmdline(8, 0x7ffc30844f78, 0x7ffc30844d00) {
   0.781 us [ 668501] |     memset(0x7ffc30844bc0, 0, 48);
 147.806 us [ 668501] |     getopt(8, 0x7ffc30844f78, "hw:b:t:T:f:sn:g:j:k:l:p:y:") = 115;
   0.271 us [ 668501] |     getopt(8, 0x7ffc30844f78, "hw:b:t:T:f:sn:g:j:k:l:p:y:") = 98;
   0.120 us [ 668501] |     getopt(8, 0x7ffc30844f78, "hw:b:t:T:f:sn:g:j:k:l:p:y:") = 84;
   0.091 us [ 668501] |     getopt(8, 0x7ffc30844f78, "hw:b:t:T:f:sn:g:j:k:l:p:y:") = 119;
   0.090 us [ 668501] |     getopt(8, 0x7ffc30844f78, "hw:b:t:T:f:sn:g:j:k:l:p:y:") = -1;
   0.140 us [ 668501] |     set_buffer_sizes(0x7ffc30844d00, 0x7ffc30844bc0);
   0.120 us [ 668501] |     set_intval("NULL", 100) = 100;
            [ 668501] |     set_intval("1", 4) {
   0.441 us [ 668501] |       atoi("1") = 1;
   0.851 us [ 668501] |     } = 1; /* set_intval */
            [ 668501] |     set_intval("60", 8) {
   0.100 us [ 668501] |       atoi("60") = 60;
   0.351 us [ 668501] |     } = 60; /* set_intval */
   0.100 us [ 668501] |     memset(0x7ffc30844d48, 0, 128);
            [ 668501] |     init_addr() {
   0.351 us [ 668501] |       strlen("[::]:1080") = 9;
   0.421 us [ 668501] |       strncpy(0x7ffc30844b00, "[::]:1080", 10);
   0.101 us [ 668501] |       atoi("1080") = 1080;
   0.381 us [ 668501] |       htons();
   0.631 us [ 668501] |       inet_pton(AF_INET6, "::", 0x7ffc30844d50) = 1;
   2.895 us [ 668501] |     } /* init_addr */
 157.715 us [ 668501] |   } = 0; /* handle_cmdline */
            [ 668501] |   init_pctx(0x7ffc30844c30, 0x7ffc30844d00) {
   1.723 us [ 668501] |     eventfd();
   0.271 us [ 668501] |     malloc(64) = 0x5562a7343a00;
            [ 668501] |     socks5_init(0x7ffc30844c40, 0x7ffc30844bf0) {
   0.100 us [ 668501] |       malloc(56) = 0x5562a7444da0;
   0.341 us [ 668501] |     } = 0; /* socks5_init */
   3.116 us [ 668501] |   } = 0; /* init_pctx */
   0.601 us [ 668501] |   sigaction(SIGTERM, 0x7ffc30844c60, 0) = 0;
   0.240 us [ 668501] |   sigaction(SIGINT, 0x7ffc30844c60, 0) = 0;
            [ 668501] |   setfdlimit() {
   0.902 us [ 668501] |     getrlimit();
   0.601 us [ 668501] |     setrlimit();
   0.271 us [ 668501] |     __errno_location();
   2.244 us [ 668501] |   } = 2; /* setfdlimit */
            [ 668501] |   spawn_threads(0x7ffc30844c30) {
            [ 668501] |     init_tctx(0x5562a7343a00, 0x7ffc30844c30) {
            [ 668501] |       init_container(0x5562a7343a28, 100) {
   1.844 us [ 668501] |         calloc(100, 8) = 0x5562a7375970;
   2.214 us [ 668501] |       } = 0; /* init_container */
            [ 668501] |       prepare_tcp_serv(0x5562a7343a00) {
   7.293 us [ 668501] |         socket(AF_INET6, SOCK_STREAM, 0) = 7;
   1.663 us [ 668501] |         setsockopt();
   0.331 us [ 668501] |         setsockopt();
   3.446 us [ 668501] |         bind(7, 0x7ffc30844d48, 128) = 0;
   2.975 us [ 668501] |         listen();
   1.823 us [ 668501] |         epoll_create(1) = 8;
            [ 668501] |         register_events(7, 8, 1, 0, 0x2000000000000) {
            [ 668501] |           custom_epoll_ctl(7, 8, 1, 0, 0x2000000000000, 1) {
   1.723 us [ 668501] |             epoll_ctl(8, EPOLL_CTL_ADD, 7, 0x7ffc30844b0c) = 0;
   2.174 us [ 668501] |           } = 0; /* custom_epoll_ctl */
   2.485 us [ 668501] |         } = 0; /* register_events */
            [ 668501] |         register_events(6, 8, 1, 0, 0x1000000000000) {
            [ 668501] |           custom_epoll_ctl(6, 8, 1, 0, 0x1000000000000, 1) {
   0.801 us [ 668501] |             epoll_ctl(8, EPOLL_CTL_ADD, 6, 0x7ffc30844b0c) = 0;
   1.052 us [ 668501] |           } = 0; /* custom_epoll_ctl */
   1.223 us [ 668501] |         } = 0; /* register_events */
  22.632 us [ 668501] |       } = 0; /* prepare_tcp_serv */
  25.387 us [ 668501] |     } = 0; /* init_tctx */
            [ 668501] |     start_tcp_serv(0x5562a7343a00) {
            [ 668501] |       epoll_wait(8, 0x7ffc308433b0, 512, -1) {
  12.637  s [ 668501] |         /* linux:schedule */
            [ 668501] |         signal_handler(15) {
   7.524 us [ 668501] |           write(6, 0x7ffc30842720, 8) = 8;
  12.663 us [ 668501] |         } /* signal_handler */
  12.637  s [ 668501] |       } = -1; /* epoll_wait */
   0.251 us [ 668501] |       __errno_location();
            [ 668501] |       cleanup_tctx(0x5562a7343a00) {
  21.560 us [ 668501] |         close(7) = 0;
   3.727 us [ 668501] |         close(8) = 0;
   1.723 us [ 668501] |         free(0x5562a7375970);
  29.274 us [ 668501] |       } /* cleanup_tctx */
  12.637  s [ 668501] |     } = 4; /* start_tcp_serv */
  12.637  s [ 668501] |   } = 4; /* spawn_threads */
            [ 668501] |   cleanup_resources(0x7ffc30844c30) {
   0.261 us [ 668501] |     join_threads(0x7ffc30844c30);
            [ 668501] |     socks5_free_ctx(0x5562a7444da0) {
   0.210 us [ 668501] |       free(0x5562a7444da0);
   0.662 us [ 668501] |     } /* socks5_free_ctx */
   0.190 us [ 668501] |     free(0x5562a7343a00);
   2.755 us [ 668501] |     close(6) = 0;
   5.059 us [ 668501] |   } /* cleanup_resources */
  12.637  s [ 668501] | } = 0; /* main */

thanks for making this great tool! ^^

[honggyukim]

oh, problem solved, it seems it must compiled with -pg flag instead of finstrument-functions :)

Right. You can see the explanation about it at https://github.com/namhyung/uftrace/blob/master/doc/uftrace-live.md#arguments and it says as follows.
"Note that these arguments and return value are recorded only if the executable was built with the -pg option. Executables built with -finstrument-functions will ignore it except for library calls. Recording of arguments and return values only works with user-level functions for now."

thanks for making this great tool! ^^

Thanks for your encouraging words!

[namhyung]

Right, -finstrument-functions will call uftrace with different arguments so it cannot see the originals.