make uftrace more friendly to daemon programs #1883

shen390s · 2024-02-05T06:45:59Z

According Advanced Programming in the UNIX® Environment,, lots of daemon program will close all file descriptors to detach from the daemon startup environment to prevent it from interaction with terminal status changes.

uftrace will get into trouble when it has been used to trace this type of programs.

Sample programs:

#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>

int fact(int n) {
    if ( n == 0 ) {
       return 1;
    }

    return n * fact(n-1);
}

int test1(int n)
{
    FILE *fp = fopen("/dev/tty", "a+");

    fprintf(fp, "%d! = %d\n", n, fact(n));

    fclose(fp);

    return 0;
}

void closex()
{
    int i;
    int max = sysconf(_SC_OPEN_MAX);

    for(i = max; i > 2; i -- ) {
       close(i);
    }

}

int main(int argc, char *argv[]) {
    int i;
    int pid;

    closex();

    pid = fork();

    if (pid == 0 ) {
       for(i = 0; i < 3; i ++) {
           test1(i);
       }
       exit(0);
    }

    wait(NULL);

    return 0;
}

Error from uftrace:

$ uftrace ./test
mcount: /data/users/rshen/works/uftrace/libmcount/misc.c:85:uftrace_send_message
 ERROR: writing shmem name to pipe: Bad file descriptor
# DURATION     TID     FUNCTION
$

The reason of the problem is that uftrace will make the program load libmcount.so before main() has been called, in libmcount.so, it will open a file descriptor(this case fd == 3) to talk to uftrace, but after main() has been entered, closex() will close all file descriptors, this will cause the. problem.

Output of uftrace with PR:

$ uftrace ./test
0! = 1
1! = 1
2! = 2
# DURATION     TID     FUNCTION
            [ 30304] | main() {
 853.126 us [ 30304] |   closex();
            [ 30304] |   /* linux:sched-out */
            [ 30307] | test1() {
   0.217 us [ 30307] |   fact();
  94.361 us [ 30307] | } /* test1 */
            [ 30307] | test1() {
            [ 30307] |   fact() {
   0.182 us [ 30307] |     fact();
   0.893 us [ 30307] |   } /* fact */
  27.367 us [ 30307] | } /* test1 */
            [ 30307] | test1() {
            [ 30307] |   fact() {
            [ 30307] |     fact() {
   0.163 us [ 30307] |       fact();
   0.700 us [ 30307] |     } /* fact */
   1.038 us [ 30307] |   } /* fact */
  23.406 us [ 30307] | } /* test1 */
   1.112 ms [ 30304] |   /* linux:sched-in */
   2.361 ms [ 30304] | } /* main */

Rongsong

namhyung

Thanks for the PR. Please squash the second commit to the first, we don't need to format change separately.

Also I'm aware of the limitation on the daemon programs. But it's not the primary target of uftrace since it wants the target process finish (to know when it can end tracing). More importantly, your change would hurt the performance because it requires two more system call when it sends a message to uftrace process.

I think we don't need to do it everytime. You can cache the fd and use it later.

paranlee · 2024-02-06T05:09:14Z

This patch solve #1016 issue. Thank you @shen390s ! 😁

shen390s · 2024-02-07T03:38:48Z

Thanks for the PR. Please squash the second commit to the first, we don't need to format change separately.

Also I'm aware of the limitation on the daemon programs. But it's not the primary target of uftrace since it wants the target process finish (to know when it can end tracing). More importantly, your change would hurt the performance because it requires two more system call when it sends a message to uftrace process.

I think we don't need to do it everytime. You can cache the fd and use it later.

I have checked the code which the PR can give side affects to performance and I think the side affect to performance may be acceptable.

Following are the part which the PR may give affect to:

$ ag uftrace_send_message .
libmcount/misc.c
61:void uftrace_send_message(int type, void *data, size_t len)

libmcount/mcount.c
548:		uftrace_send_message(UFTRACE_MSG_FINISH, NULL, 0);
609:	uftrace_send_message(UFTRACE_MSG_TASK_END, &tmsg, sizeof(tmsg));
782:	uftrace_send_message(UFTRACE_MSG_TASK_START, &tmsg, sizeof(tmsg));
1734:	uftrace_send_message(UFTRACE_MSG_FORK_START, &tmsg, sizeof(tmsg));
1770:	uftrace_send_message(UFTRACE_MSG_FORK_END, &tmsg, sizeof(tmsg));

libmcount/plthook.c
710:	uftrace_send_message(UFTRACE_MSG_FORK_START, &tmsg, sizeof(tmsg));
711:	uftrace_send_message(UFTRACE_MSG_FORK_END, &tmsg, sizeof(tmsg));

libmcount/internal.h
305:extern void uftrace_send_message(int type, void *data, size_t len);

libmcount/record.c
86:	uftrace_send_message(UFTRACE_MSG_REC_START, buf, strlen(buf));
164:	uftrace_send_message(UFTRACE_MSG_REC_START, buf, strlen(buf));
175:		uftrace_send_message(UFTRACE_MSG_LOST, &shmem->losts, sizeof(shmem->losts));
189:	uftrace_send_message(UFTRACE_MSG_REC_END, buf, strlen(buf));

$ ag send_dlopen_msg .
libmcount/wrap.c
33:static void send_dlopen_msg(struct mcount_thread_data *mtdp, const char *sess_id,
99:	send_dlopen_msg(data->mtdp, mcount_session_name(), data->timestamp, info->dlpi_addr,
[rshen@rh79shen1 uftrace]$ ag send_session_msg .
libmcount/mcount.c
488:static void send_session_msg(struct mcount_thread_data *mtdp, const char *sess_id)
741:	send_session_msg(&mtd, mcount_session_name());

Following are the potential scenarios which can be affected:

new thread/process created
thread/process exit
start/end recording
dll loading
share memory full and need to get new buffer

Rongsong

namhyung

I've checked it with misc/bench and it doesn't seems to have a noticeable performance impact. Maybe because it's called not very often.

namhyung · 2024-02-07T06:34:15Z

libmcount/internal.h

@@ -185,7 +185,7 @@ extern uint64_t mcount_threshold; /* nsec */
 extern unsigned mcount_minsize;
 extern pthread_key_t mtd_key;
 extern int shmem_bufsize;
-extern int pfd;
+extern int mcount_get_pfd(void);


Can you please move it to below together with other function declarations?

namhyung · 2024-02-07T07:06:13Z

libmcount/mcount.c

@@ -1802,9 +1797,25 @@ static void mcount_script_init(enum uftrace_pattern_type patt_type)
 	strv_free(&info.cmds);
 }

-static __used void mcount_startup(void)
+int mcount_get_pfd(void)


I think it's better to move this to misc.c file.

Thanks. I will updated it soon

namhyung

Please change the commit message like this:

"mcount: Do not keep FD for message channel

uftrace and libmcount communicate using a pipe in the data directory.
Historically it used to have an unnamed pipe but it's using a FIFO which
means it doesn't need to keep the file descriptor open.

Instead it can open the file whenever it needs to send a message. While
this would bring more overheads, a micro benchmark showed it's very
small. The upside is that it can work with daemon programs which close
all file descriptors at the beginning.

Signed-off-by: (put your name and email)"

namhyung · 2024-02-21T17:50:31Z

Hmm.. this change makes almost every tests failing.

shen390s · 2024-02-22T08:46:30Z

Hmm.. this change makes almost every tests failing.

Can you give more detail information?

namhyung · 2024-02-23T06:25:35Z

It fails with NZ meaning 'non-zero return value'.

$ git log -2 --oneline --no-decorate
3c9dad8a mcount: Do not keep FD for message channel
25b90354 python: Fix GC isn't working correctly.

$ make -j8 runtest
  TEST     test_all
Start 287 tests with 8 worker

Compiler                  gcc                                           clang                                       
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os
001 basic               : NZ NZ NZ NZ OK NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ OK NZ NZ OK NZ
002 argument            : NZ OK NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
003 thread              : NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
004 filter_F            : NZ NZ NZ NZ NZ OK NZ NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ OK OK NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
005 filter_N            : NZ NZ OK NZ NZ NZ NZ NZ NZ NZ OK NZ OK NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
006 filter_FN           : NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
007 library             : OK NZ NZ NZ NZ NZ OK NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ OK NZ NZ NZ
008 daemon              : OK NZ NZ NZ NZ NZ OK NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
009 fork                : NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ OK NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ OK NZ NZ
010 forkexec            : NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
011 vforkexec           : NZ NZ OK NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
...

When I run the command manually, it sometimes fails with no data but mostly works fine.

shen390s · 2024-02-26T07:56:46Z

It fails with NZ meaning 'non-zero return value'.

$ git log -2 --oneline --no-decorate
3c9dad8a mcount: Do not keep FD for message channel
25b90354 python: Fix GC isn't working correctly.

$ make -j8 runtest
  TEST     test_all
Start 287 tests with 8 worker

Compiler                  gcc                                           clang                                       
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os
001 basic               : NZ NZ NZ NZ OK NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ OK NZ NZ OK NZ
002 argument            : NZ OK NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
003 thread              : NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
004 filter_F            : NZ NZ NZ NZ NZ OK NZ NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ OK OK NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
005 filter_N            : NZ NZ OK NZ NZ NZ NZ NZ NZ NZ OK NZ OK NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
006 filter_FN           : NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
007 library             : OK NZ NZ NZ NZ NZ OK NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ OK NZ NZ NZ
008 daemon              : OK NZ NZ NZ NZ NZ OK NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
009 fork                : NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ OK NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ OK NZ NZ
010 forkexec            : NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
011 vforkexec           : NZ NZ OK NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ  NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ
...

When I run the command manually, it sometimes fails with no data but mostly works fine.

Following are test run in my environment(I have no clang installed)

[rshen@rh79shen1 uftrace]$ make -j8 runtest
  TEST     test_run
Start 287 tests with 8 worker

Compiler                  gcc                                           clang
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os
001 basic               : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
002 argument            : NG NG NG NG NG OK NZ OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
003 thread              : NG NG NG NG NG OK NG OK NG OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
004 filter_F            : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
005 filter_N            : OK NZ OK OK OK OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
006 filter_FN           : OK OK OK OK OK OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
007 library             : OK OK OK OK OK OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
008 daemon              : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
009 fork                : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
010 forkexec            : NG NG NG NG NG OK OK NZ OK OK TM TM TM TM TM  TM TM TM TM TM TM TM TM TM TM TM TM TM TM TM
011 vforkexec           : NG NG NG NG NG OK NG OK OK OK TM TM TM TM TM  TM TM TM TM TM TM TM TM TM TM TM TM TM TM TM
012 demangle            : OK OK OK OK OK OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
013 signal              : NG NG NG NG NZ OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
014 ucontext            : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
015 longjmp             : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
016 alloca              : NG NG NG NG NG OK OK OK NZ OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
017 no_libcall          : OK OK OK OK OK OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
018 filter_regex        : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
019 full_depth          : OK OK OK OK OK OK OK NZ OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
020 filter_depth        : OK OK OK OK OK OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
021 filter_plt          : NZ NZ NZ NZ NZ OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
022 filter_kernel       : SK SK SK SK SK SK SK SK SK SK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
023 replay_filter       : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
024 report_basic        : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
025 report_s_call       : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
026 filter_trigger      : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
027 replay_filter_d     : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
028 replay_backtrace    : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
029 trigger_only        : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
030 replay_trigger      : OK OK OK OK OK OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
031 filter_demangle1    : NG NG NG NG NG OK NZ OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
032 filter_demangle2    : NZ NZ NZ NZ NZ OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
033 filter_demangle3    : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
034 filter_demangle4    : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
035 filter_demangle5    : NG NG NG NZ NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
036 replay_filter_N     : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
037 trace_onoff         : NG NG NG NZ NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
038 trace_disable       : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
039 trace_onoff_F       : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
040 replay_onoff        : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
041 replay_onoff_N      : NG NZ NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
042 live_disable        : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
043 full_demangle       : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
044 report_avg_total    : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
045 report_avg_self     : NG NG NG NG NG NZ OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
046 report_task         : OK NG OK NG NG OK OK OK OK NG BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
047 signal2             : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
048 malloc_impl         : OK OK OK OK OK OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
049 column_view         : NG NG NG NG NG NG NZ OK OK NG BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
050 no_pltbind          : NZ NG NG NG NG NG OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
051 return              : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
052 nested_func         : NG NG NG NG NG NG NG NG NG NG BI BI BI BI BI  SK SK SK SK SK SK SK SK SK SK SK SK SK SK SK
053 filter_time         : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
054 filter_time_F       : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
055 filter_time_N       : OK OK OK OK OK OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
056 filter_time_T       : OK OK OK OK OK OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
057 filter_time_D       : OK OK OK OK OK OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
058 arg_int             : OK OK OK OK OK SK SK SK SK SK BI BI BI BI BI  BI BI BI BI BI SK SK SK SK SK TM TM TM TM TM
059 arg_str             : OK OK OK OK OK SK SK SK SK SK BI BI BI BI BI  BI BI BI BI BI SK SK SK SK SK TM TM TM TM TM
060 arg_fmt             : OK OK OK OK OK SK SK SK SK SK BI BI BI BI BI  BI BI BI BI BI SK SK SK SK SK TM TM TM TM TM
061 arg_plt             : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
062 arg_char            : OK OK OK OK OK SK SK SK SK SK BI BI BI BI BI  BI BI BI BI BI SK SK SK SK SK BI BI BI BI BI
063 retval              : OK OK OK OK OK SK SK SK SK SK BI BI BI BI BI  BI BI BI BI BI SK SK SK SK SK TM TM TM TM TM
064 trigger_trace       : NG NG NG NG NG OK NZ OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
065 arg_order           : OK OK OK OK OK SK SK SK SK SK BI BI BI BI BI  BI BI BI BI BI SK SK SK SK SK TM TM TM TM TM
066 no_demangle         : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
067 report_diff         : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
068 filter_time_A       : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
069 graph               : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
070 graph_backtrace     : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
071 graph_depth         : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
072 no_comment          : NG NG NG NG NG OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
073 lib_filter          : OK OK OK OK OK OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
074 lib_trigger         : OK OK OK OK OK OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
075 lib_arg             : OK OK OK OK OK SK SK SK SK SK BI BI BI BI BI  BI BI BI BI BI SK SK SK SK SK BI BI BI BI BI
076 lib_replay_F        : OK OK OK OK OK OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
077 lib_replay_T        : OK OK OK OK OK OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
078 max_stack           : OK OK OK OK OK OK OK OK OK OK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
079 replay_kernel_D     : SK SK SK SK SK SK SK SK SK SK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
080 replay_kernel_D2    : SK SK SK SK SK SK SK SK SK SK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
081 kernel_depth        : SK SK SK SK SK SK SK SK SK SK BI BI BI BI BI  BI BI BI BI BI BI BI BI BI BI BI BI BI BI BI
082 arg_many            : NG NG NG NG NG SK SK SK SK SK BI BI BI BI BI  BI BI BI BI BI SK SK SK SK SK BI BI BI BI BI

Also I run test with master, which looks similiar.

Is it possible that test case is not robust enough?

Rongsong

shen390s · 2024-02-26T08:00:33Z

And something error with '-j8'(It seems that confliction between test cases) which should not be related to this PR.

uftrace: /data/users/rshen/works/uftrace/cmds/recv.c:49:server_socket
 ERROR: socket bind failed (port: 45721): Address already in use
uftrace: /data/users/rshen/works/uftrace/cmds/recv.c:124:setup_client_socket
 ERROR: socket connect failed (host: localhost, port: 45721): Connection refused
uftrace: /data/users/rshen/works/uftrace/cmds/record.c:2228:do_child_exec
 ERROR: waiting for parent failed: No such file or directory

namhyung · 2024-02-27T17:03:08Z

Hmm... I don't know. In my environment, it works on master but not with your change. I need to look at where it returns non-zero. By the way, test output should not have columns for clang if it's not installed..

About the errors in the recv tests, yeah there is a problem somewhere. :) But as you mentioned it's not your fault.

namhyung · 2024-03-05T06:18:05Z

I've tested it again on top of the current master. But it still fails due to no data.

$ make runtest TESTARG='-vpO2 001'
  TEST     test_run
Start 1 tests without worker pool

Compiler                  gc  cl
Runtime test case         pg  pg
------------------------: O2  O2
build command: gcc -o t-abc -fno-inline -fno-builtin -fno-ipa-cp -fno-omit-frame-pointer -D_FORTIFY_SOURCE=0  -pg -O2  -fno-ipa-sra  s-abc.c   
test command: /home/namhyung/project/uftrace/uftrace live --no-pager --no-event --libmcount-path=/home/namhyung/project/uftrace   -N memcpy t-abc
WARN: cannot open record data: /tmp/uftrace-live-C2zj2f: No data available
build command: clang -o t-abc -fno-inline -fno-builtin -fno-ipa-cp -fno-omit-frame-pointer -D_FORTIFY_SOURCE=0  -pg -O2   s-abc.c   
test command: /home/namhyung/project/uftrace/uftrace live --no-pager --no-event --libmcount-path=/home/namhyung/project/uftrace   -N memcpy t-abc
WARN: cannot open record data: /tmp/uftrace-live-ncy1lB: No data available
001 basic               : NZ  NZ

shen390s · 2024-03-18T10:11:43Z

test in my environment:

-bash-4.2$  make runtest TESTARG='-vpO2 001'
  TEST     test_run
Start 1 tests without worker pool

Compiler                  gc
Runtime test case         pg
------------------------: O2
build command: gcc -o t-abc -fno-inline -fno-builtin -fno-ipa-cp -fno-omit-frame-pointer -D_FORTIFY_SOURCE=0  -pg -O2 -fno-ipa-sra  s-abc.c
test command: /data/users/rshen/works/uftrace/uftrace live --no-pager --no-event --libmcount-path=/data/users/rshen/works/uftrace   -N memcpy t-abc
=========== original ===========
# DURATION     TID     FUNCTION
            [ 25811] | main() {
            [ 25811] |   a() {
            [ 25811] |     b() {
   0.452 us [ 25811] |       c();
   1.628 us [ 25811] |     } /* b */
   1.975 us [ 25811] |   } /* a */
   2.615 us [ 25811] | } /* main */

===========  result  ===========
main() {
   a() {
     b() {
       c();
     } /* b */
   } /* a */
 } /* main */
=========== expected ===========
main() {
   a() {
     b() {
       c() {
         getpid();
       } /* c */
     } /* b */
   } /* a */
 } /* main */
001 basic               : NG

-bash-4.2$ git branch
* daemon_friendly
  master
  working

shen390s · 2024-03-19T02:49:03Z

Also the test result of the newest master:

Start 1 tests without worker pool

Compiler                  gc
Runtime test case         pg
------------------------: O2
build command: gcc -o t-abc -fno-inline -fno-builtin -fno-ipa-cp -fno-omit-frame-pointer -D_FORTIFY_SOURCE=0  -pg -O2  -fno-ipa-sra  s-abc.c
test command: /data/users/rshen/works/uftrace/uftrace live --no-pager --no-event --libmcount-path=/data/users/rshen/works/uftrace   -N memcpy t-abc
=========== original ===========
# DURATION     TID     FUNCTION
            [ 15197] | main() {
            [ 15197] |   a() {
            [ 15197] |     b() {
   0.787 us [ 15197] |       c();
   2.303 us [ 15197] |     } /* b */
   2.906 us [ 15197] |   } /* a */
   4.128 us [ 15197] | } /* main */

===========  result  ===========
main() {
   a() {
     b() {
       c();
     } /* b */
   } /* a */
 } /* main */
=========== expected ===========
main() {
   a() {
     b() {
       c() {
         getpid();
       } /* c */
     } /* b */
   } /* a */
 } /* main */
001 basic               : NG

-bash-4.2$ git branch
  daemon_friendly
* master
  working

shen390s · 2024-03-19T02:54:59Z

running strace with command:

strace -f -o /tmp/log -v -s 1024 /data/users/rshen/works/uftrace/uftrace live --no-pager --no-event --libmcount-path=/data/users/rshen/works/uftrace   -N memcpy t-abc

and check output of uftrace data file operations:

-bash-4.2$ cat /tmp/log |grep open  |grep uftrace
16827 open("/tmp/uftrace-live-kfNOTT", O_RDWR|O_CREAT|O_EXCL, 0600) = 3
16827 open("/tmp/uftrace-live-kfNOTT/default.opts", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
16827 open("/tmp/uftrace-live-kfNOTT/.channel", O_RDONLY|O_NONBLOCK <unfinished ...>
16828 open("/data/users/rshen/works/uftrace/libmcount/libmcount.so", O_RDONLY|O_CLOEXEC) = 3
16828 open("/tmp/uftrace-live-kfNOTT/.channel", O_WRONLY) = 3
16828 open("/tmp/uftrace-live-kfNOTT/sid-423bf17adcbb9f7f.map", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 5
16828 open("/data/users/rshen/works/uftrace/tests/t-abc", O_RDONLY) = 6
16828 open("/data/users/rshen/works/uftrace/libmcount/libmcount.so", O_RDONLY) = 6
16828 open("/data/users/rshen/works/uftrace/tests/t-abc", O_RDONLY) = 4
16828 open("/data/users/rshen/works/uftrace/tests/t-abc", O_RDONLY) = 4
16828 open("/data/users/rshen/works/uftrace/tests/t-abc", O_RDONLY) = 4
16828 open("/data/users/rshen/works/uftrace/tests/t-abc", O_RDONLY) = 4
16828 open("/data/users/rshen/works/uftrace/tests/t-abc", O_RDONLY) = 4
16828 open("/dev/shm/uftrace-423bf17adcbb9f7f-16828-000", O_RDWR|O_CREAT|O_TRUNC|O_NOFOLLOW|O_CLOEXEC, 0600 <unfinished ...>
16828 open("/dev/shm/uftrace-423bf17adcbb9f7f-16828-001", O_RDWR|O_CREAT|O_TRUNC|O_NOFOLLOW|O_CLOEXEC, 0600 <unfinished ...>
16827 open("/tmp/uftrace-live-kfNOTT/task.txt", O_WRONLY|O_CREAT|O_APPEND, 0666 <unfinished ...>
16827 open("/tmp/uftrace-live-kfNOTT/task.txt", O_WRONLY|O_CREAT|O_APPEND, 0666) = 4
16827 open("/tmp/uftrace-live-kfNOTT/info", O_WRONLY|O_CREAT|O_TRUNC, 0644 <unfinished ...>
16827 openat(AT_FDCWD, "/tmp/uftrace-live-kfNOTT", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 7
16827 open("/tmp/uftrace-live-kfNOTT/task.txt", O_RDONLY) = 7
16827 open("/dev/shm/uftrace-423bf17adcbb9f7f-16828-000", O_RDWR|O_NOFOLLOW|O_CLOEXEC) = 4
16827 open("/tmp/uftrace-live-kfNOTT/16828.dat", O_WRONLY|O_CREAT|O_APPEND, 0644) = 4
16827 openat(AT_FDCWD, "/tmp/uftrace-live-kfNOTT", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4
16827 open("/tmp/uftrace-live-kfNOTT/sid-423bf17adcbb9f7f.map", O_RDONLY) = 4
16827 open("/tmp/uftrace-live-kfNOTT/sid-423bf17adcbb9f7f.map.tmp", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 5
16827 open("/data/users/rshen/works/uftrace/tests/t-abc", O_RDONLY) = 6
16827 open("/data/users/rshen/works/uftrace/libmcount/libmcount.so", O_RDONLY) = 6
16827 openat(AT_FDCWD, "/tmp/uftrace-live-kfNOTT", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4
16827 open("/tmp/uftrace-live-kfNOTT/sid-423bf17adcbb9f7f.map", O_RDONLY) = 4
16827 open("/data/users/rshen/works/uftrace/tests/t-abc", O_RDONLY) = 4
16827 open("/data/users/rshen/works/uftrace/tests/t-abc", O_RDONLY) = 4
16827 open("/data/users/rshen/works/uftrace/tests/t-abc", O_RDONLY) = 4
16827 open("/data/users/rshen/works/uftrace/tests/t-abc", O_RDONLY) = 4
16827 open("/tmp/uftrace-live-kfNOTT/libz.so.1.2.7.sym", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC, 0666) = 4
16827 open("/tmp/uftrace-live-kfNOTT/librt-2.17.so.sym", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC, 0666) = 4
16827 open("/tmp/uftrace-live-kfNOTT/libpthread-2.17.so.sym", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC, 0666) = 4
16827 open("/tmp/uftrace-live-kfNOTT/libm-2.17.so.sym", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC, 0666) = 4
16827 open("/tmp/uftrace-live-kfNOTT/liblzma.so.5.2.2.sym", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC, 0666) = 4
16827 open("/tmp/uftrace-live-kfNOTT/libgcc_s-4.8.5-20150702.so.1.sym", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC, 0666) = 4
16827 open("/tmp/uftrace-live-kfNOTT/libelf-0.176.so.sym", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC, 0666) = 4
16827 open("/tmp/uftrace-live-kfNOTT/libdw-0.176.so.sym", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC, 0666) = 4
16827 open("/tmp/uftrace-live-kfNOTT/libdl-2.17.so.sym", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC, 0666) = 4
16827 open("/tmp/uftrace-live-kfNOTT/libcapstone.so.4.sym", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC, 0666) = 4
16827 open("/tmp/uftrace-live-kfNOTT/libc-2.17.so.sym", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC, 0666) = 4
16827 open("/tmp/uftrace-live-kfNOTT/libbz2.so.1.0.6.sym", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC, 0666) = 4
16827 open("/tmp/uftrace-live-kfNOTT/ld-2.17.so.sym", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC, 0666) = 4
16827 open("/data/users/rshen/works/uftrace/tests/t-abc", O_RDONLY) = 4
16827 open("/tmp/uftrace-live-kfNOTT/t-abc.sym", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC, 0666) = 4
16827 open("/tmp/uftrace-live-kfNOTT/info", O_RDONLY) = 4
16827 open("/tmp/uftrace-live-kfNOTT/task", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/task.txt", O_RDONLY) = 4
16827 open("/tmp/uftrace-live-kfNOTT/sid-423bf17adcbb9f7f.map", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/t-abc.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/t-abc.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libbz2.so.1.0.6.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libbz2.so.1.0.6.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/liblzma.so.5.2.2.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/liblzma.so.5.2.2.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libz.so.1.2.7.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libz.so.1.2.7.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libgcc_s-4.8.5-20150702.so.1.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libgcc_s-4.8.5-20150702.so.1.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libm-2.17.so.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libm-2.17.so.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libpthread-2.17.so.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libpthread-2.17.so.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libcapstone.so.4.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libcapstone.so.4.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libdw-0.176.so.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libdw-0.176.so.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libelf-0.176.so.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libelf-0.176.so.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/librt-2.17.so.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/librt-2.17.so.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libdl-2.17.so.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libdl-2.17.so.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libc-2.17.so.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/libc-2.17.so.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/ld-2.17.so.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/ld-2.17.so.sym", O_RDONLY) = 5
16827 open("/tmp/uftrace-live-kfNOTT/t-abc.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/t-abc-db04.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libbz2.so.1.0.6.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libbz2.so.1.0.6-e31f.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/liblzma.so.5.2.2.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/liblzma.so.5.2.2-f744.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libz.so.1.2.7.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libz.so.1.2.7-8f3f.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libgcc_s-4.8.5-20150702.so.1.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libgcc_s-4.8.5-20150702.so.1-edf5.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libm-2.17.so.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libm-2.17.so-7615.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libpthread-2.17.so.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libpthread-2.17.so-e10c.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libcapstone.so.4.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libcapstone.so.4-6370.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libdw-0.176.so.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libdw-0.176.so-70b9.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libelf-0.176.so.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libelf-0.176.so-72ff.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libstdc++.so.6.0.19.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libstdc++.so.6.0.19-09cf.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/librt-2.17.so.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/librt-2.17.so-3e44.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libdl-2.17.so.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libdl-2.17.so-7f2e.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libc-2.17.so.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/libc-2.17.so-fc4f.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/ld-2.17.so.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/ld-2.17.so-62c4.dbg", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 open("/tmp/uftrace-live-kfNOTT/extern.dat", O_RDONLY) = -1 ENOENT (没有那个文件或目录)
16827 openat(AT_FDCWD, "/tmp/uftrace-live-kfNOTT", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4
16827 open("/tmp/uftrace-live-kfNOTT/16828.dat", O_RDONLY) = 4
16827 openat(AT_FDCWD, "/tmp/uftrace-live-kfNOTT", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 4

shen390s · 2024-03-19T03:03:53Z

@namhyung can you try to run strace -f on "/home/namhyung/project/uftrace/uftrace live --no-pager --no-event --libmcount-path=/home/namhyung/project/uftrace -N memcpy t-abc" ?

Rongsong

namhyung · 2024-03-19T08:24:42Z

Hmm.. it sometimes doesn't get the message in error cases.

Normally uftrace needs to get at least the following messages:

uftrace: MSG SESSION: 4120397: /home/namhyung/tmp/t-progs/t-abc (9d45ba09f9ba9b13)
uftrace: MSG START: /uftrace-9d45ba09f9ba9b13-4120397-000
uftrace: MSG TASK_START : 4120397/4120397

But it doesn't get the last two messages even if mcount code sent them. So it thought there's no task (and no data) and fail.

namhyung · 2024-03-19T08:36:30Z

Here's a strace result for open, write and close. The pid 4119794 is a parent (uftrace) and 4119795 is a child (t-abc). I've added some comments.

# child sends UFTRACE_MSG_SESSION
[pid 4119795] openat(AT_FDCWD, "/tmp/uftrace-live-OisFWc/.channel", O_WRONLY) = 3
[pid 4119795] writev(3, [{iov_base="\316\372\7\0H\0\0\0", iov_len=8}, {iov_base="?\244\275\322U\360\1\0\363\334>\0\363\334>\0d302a8640923c386"..., iov_len=40}, {iov_base="/home/namhyung/tmp/t-progs/t-abc", iov_len=32}], 3) = 80
[pid 4119795] close(3)                  = 0

# parent creates the task file
[pid 4119794] openat(AT_FDCWD, "/tmp/uftrace-live-OisFWc/task.txt", O_WRONLY|O_CREAT|O_APPEND, 0666) = 4

# child opens a shmem buffer
[pid 4119795] openat(AT_FDCWD, "/dev/shm/uftrace-d302a8640923c386-4119795-000", O_RDWR|O_CREAT|O_TRUNC|O_NOFOLLOW|O_CLOEXEC, 0600 <unfinished ...>

# parent got SESSION message and writes it to the task file
[pid 4119794] write(4, "SESS timestamp=545726.375240767 "..., 108) = 108

# handle the shmem buffer
[pid 4119795] <... openat resumed>)     = 3
[pid 4119795] close(3)                  = 0

# parent closes the task file
[pid 4119794] close(4)                  = 0

# child opens another shmem buffer
[pid 4119795] openat(AT_FDCWD, "/dev/shm/uftrace-d302a8640923c386-4119795-001", O_RDWR|O_CREAT|O_TRUNC|O_NOFOLLOW|O_CLOEXEC, 0600) = 3
[pid 4119795] close(3)                  = 0

# child sends UFTRACE_MSG_REC_START
[pid 4119795] openat(AT_FDCWD, "/tmp/uftrace-live-OisFWc/.channel", O_WRONLY) = 3
[pid 4119795] writev(3, [{iov_base="\316\372\1\0%\0\0\0", iov_len=8}, {iov_base="/uftrace-d302a8640923c386-411979"..., iov_len=37}], 2) = 45
[pid 4119795] close(3)                  = 0

# child sends UFTRACE_MSG_TASK_START
[pid 4119795] openat(AT_FDCWD, "/tmp/uftrace-live-OisFWc/.channel", O_WRONLY) = 3
[pid 4119795] writev(3, [{iov_base="\316\372\3\0\20\0\0\0", iov_len=8}, {iov_base="H\365\304\322U\360\1\0\363\334>\0\363\334>\0", iov_len=16}], 2) = 24
[pid 4119795] close(3)                  = 0
[pid 4119795] +++ exited with 0 +++

# parent sees the child exited
[pid 4119794] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=4119795, si_uid=657345, si_status=0, si_utime=0, si_stime=0} ---

namhyung · 2024-03-20T00:08:46Z

I'm not sure if it behaves differently depending on kernel version but it seems pipe_poll() in the kernel would set (E)POLLHUP bit in the pollfd.revents when there's no writers currently (but it had any writers before). Then the loop in do_main_loop() cannot work properly and it will move onto stop_tracing() early. Now it can race with the child writing to the pipe, if ioctl(FIONREAD) returns the remaining size of 0 and then it would sleep for 1msec. In the meantime, the child can write to pipe and exit. Now parent wakes up but it has no tasks and check_tid_list() return true and it breaks loop without reading from the pipe.

shen390s · 2024-03-20T02:37:57Z

I'm not sure if it behaves differently depending on kernel version but it seems pipe_poll() in the kernel would set (E)POLLHUP bit in the pollfd.revents when there's no writers currently (but it had any writers before). Then the loop in do_main_loop() cannot work properly and it will move onto stop_tracing() early. Now it can race with the child writing to the pipe, if ioctl(FIONREAD) returns the remaining size of 0 and then it would sleep for 1msec. In the meantime, the child can write to pipe and exit. Now parent wakes up but it has no tasks and check_tid_list() return true and it breaks loop without reading from the pipe.

It seems that we are nearly reach the cause of the problem. With this PR, when parent poll the FIFO and the peer side(child) has closed fd for FIFO writing, this may be the reason of problem.

Rongsong

namhyung · 2024-04-11T04:11:09Z

Maybe we can keep the current behavior, but add a retry logic if it detects a bad file descriptor and set the pfd again withe the new value.

shen390s · 2024-04-11T07:08:36Z

Maybe we can keep the current behavior, but add a retry logic if it detects a bad file descriptor and set the pfd again withe the new value.

Still possible to meet the same issue but with much less possible.

Can we consider to intercept close() in libc and do NOP when it tries to close the fd which we have used to talk to uftrace side?

Rongsong

namhyung · 2024-04-11T19:59:17Z

Good idea, that would work too! It seems a bit radical but I guess close() is not in the hot path so we're good.

shen390s · 2024-04-12T03:21:41Z

Good idea, that would work too! It seems a bit radical but I guess close() is not in the hot path so we're good.

quick solution:

rshen@lsfdevshen1 ~/w/uftrace (protect_pfd)> git diff master                                                                                                                                                                                    20:18:08
diff --git a/libmcount/wrap.c b/libmcount/wrap.c
index d26d9a39..97192144 100644
--- a/libmcount/wrap.c
+++ b/libmcount/wrap.c
@@ -274,6 +274,7 @@ static int (*real_posix_spawnp)(pid_t *pid, const char *file,
 static int (*real_execve)(const char *path, char *const argv[], char *const envp[]);
 static int (*real_execvpe)(const char *file, char *const argv[], char *const envp[]);
 static int (*real_fexecve)(int fd, char *const argv[], char *const envp[]);
+static int (*real_close)(int fd);

 void mcount_hook_functions(void)
 {
@@ -291,6 +292,7 @@ void mcount_hook_functions(void)
        real_execve = dlsym(RTLD_NEXT, "execve");
        real_execvpe = dlsym(RTLD_NEXT, "execvpe");
        real_fexecve = dlsym(RTLD_NEXT, "fexecve");
+        real_close = dlsym(RTLD_NEXT, "close");
 }

 __visible_default int backtrace(void **buffer, int sz)
@@ -615,6 +617,18 @@ __visible_default int fexecve(int fd, char *const argv[], char *const envp[])
        return real_fexecve(fd, argv, new_envp);
 }

+__visible_default int close(int fd)
+{
+        if (unlikely(real_close == NULL))
+                mcount_hook_functions();
+
+        if ((fd >= 0) && (fd == pfd)) {
+                return 0;
+        }
+
+        return real_close(fd);
+
+}
 #ifdef UNIT_TEST

 TEST_CASE(mcount_wrap_dlopen)

and test results with this solution:

bash-4.2$ which uftrace
/home/rshen/works/test.uftrace/bin/uftrace
bash-4.2$ uftrace ./test
0! = 1
1! = 1
2! = 2
# DURATION     TID     FUNCTION
            [ 14515] | main() {
 644.419 us [ 14515] |   closex();
            [ 14515] |   /* linux:sched-out */
            [ 14520] | test1() {
   0.351 us [ 14520] |   fact();
 174.935 us [ 14520] | } /* test1 */
            [ 14520] | test1() {
            [ 14520] |   fact() {
   0.252 us [ 14520] |     fact();
   1.415 us [ 14520] |   } /* fact */
 471.115 us [ 14520] |   /* linux:schedule (pre-empted) */
 565.402 us [ 14520] | } /* test1 */
            [ 14520] | test1() {
            [ 14520] |   fact() {
            [ 14520] |     fact() {
   0.271 us [ 14520] |       fact();
   1.478 us [ 14520] |     } /* fact */
   1.989 us [ 14520] |   } /* fact */
  60.058 us [ 14520] | } /* test1 */
   2.993 ms [ 14515] |   /* linux:sched-in */
   4.011 ms [ 14515] | } /* main */

Result of uftrace from master branch:

bash-4.2$ /usr/local/bin/uftrace test
mcount: /data/users/rshen/works/uftrace/libmcount/misc.c:85:uftrace_send_message
 ERROR: writing shmem name to pipe: Bad file descriptor
# DURATION     TID     FUNCTION

Any suggestion?

Rongsong

namhyung · 2024-04-12T15:48:53Z

Looks good. I don't think you need to check fd being positive as pfd should not be negative. Calling close() with a negative number should be failed, anyway it's a nitpick. I'm ok with the change.

shen390s · 2024-04-15T04:05:48Z

@paranlee can you check whether new solution can give you some help?

Rongsong

namhyung

The change looks good but can you please update the commit message in more detail? I think you can use "mcount": prefix in the subject line and describe what was the problem, and add the issue number. Thanks!

libmcount/wrap.c

uftrace and libmcount communicate using a pipe in the data directory. We need to keep the file descriptor open to ensure that uftrace and libmcount can communicate correctly. Some daemon programs will close all file descriptors during they startup, we need to protect file descriptor which will be used to communicate uftrace and libmcount to avoid broken communication issue. Signed-off-by: Rongsong Shen <rshen@shenrs.eu>

namhyung

Looks good, @paranlee can you please check if it works well for you?

namhyung · 2024-04-22T03:59:20Z

libmcount/wrap.c

+
+	if (unlikely(fd == pfd)) {
+		return 0;
+	}


Another nitpick: You don't need the brackets for the single line statement.

shen390s · 2024-04-24T02:24:59Z

@namhyung I think no work need to do by me.

Rongsong

shen390s · 2024-04-26T02:47:46Z

@namhyung can you merge this PR? I have no permission for this.

Rongsong

namhyung · 2024-04-26T06:50:36Z

Yep, I will wait for a few more days and merge the change.

paranlee · 2024-05-09T05:24:51Z

@shen390s @namhyung Thank you all. I tested in merged master branch. It works well!
I've updated the wiki after the issue is now working properly. :) 👍 💯

https://github.com/namhyung/uftrace/wiki/uftrace-for-Erlang-BEAM-VM#3-do-uftrace

namhyung reviewed Feb 6, 2024

View reviewed changes

paranlee mentioned this pull request Feb 6, 2024

ERROR : writing shmem name to pipe: Broken pipe #1016

Open

shen390s force-pushed the daemon_friendly branch 2 times, most recently from 44a570c to b991904 Compare February 7, 2024 03:36

shen390s force-pushed the daemon_friendly branch from b991904 to 67b295b Compare February 7, 2024 04:15

namhyung reviewed Feb 7, 2024

View reviewed changes

namhyung reviewed Feb 8, 2024

View reviewed changes

shen390s force-pushed the daemon_friendly branch from 37cc9ba to 3c9dad8 Compare February 19, 2024 08:55

shen390s force-pushed the daemon_friendly branch 2 times, most recently from 59ff786 to f5ca588 Compare April 15, 2024 04:02

namhyung reviewed Apr 19, 2024

View reviewed changes

libmcount/wrap.c Show resolved Hide resolved

shen390s force-pushed the daemon_friendly branch from f5ca588 to 10082b5 Compare April 22, 2024 03:49

namhyung approved these changes Apr 22, 2024

View reviewed changes

namhyung merged commit d79deba into namhyung:master May 1, 2024
3 checks passed

make uftrace more friendly to daemon programs #1883

make uftrace more friendly to daemon programs #1883

Conversation

shen390s commented Feb 5, 2024 • edited Loading

namhyung left a comment

Choose a reason for hiding this comment

paranlee commented Feb 6, 2024

shen390s commented Feb 7, 2024

namhyung left a comment

Choose a reason for hiding this comment

namhyung Feb 7, 2024

Choose a reason for hiding this comment

namhyung Feb 7, 2024

Choose a reason for hiding this comment

shen390s Feb 19, 2024

Choose a reason for hiding this comment

namhyung left a comment

Choose a reason for hiding this comment

namhyung commented Feb 21, 2024

shen390s commented Feb 22, 2024

namhyung commented Feb 23, 2024

shen390s commented Feb 26, 2024

shen390s commented Feb 26, 2024

namhyung commented Feb 27, 2024

namhyung commented Mar 5, 2024

shen390s commented Mar 18, 2024

shen390s commented Mar 19, 2024

shen390s commented Mar 19, 2024

shen390s commented Mar 19, 2024

namhyung commented Mar 19, 2024

namhyung commented Mar 19, 2024

namhyung commented Mar 20, 2024 • edited Loading

shen390s commented Mar 20, 2024

namhyung commented Apr 11, 2024

shen390s commented Apr 11, 2024 • edited Loading

namhyung commented Apr 11, 2024

shen390s commented Apr 12, 2024 • edited Loading

namhyung commented Apr 12, 2024 • edited Loading

shen390s commented Apr 15, 2024

namhyung left a comment

Choose a reason for hiding this comment

namhyung left a comment

Choose a reason for hiding this comment

namhyung Apr 22, 2024

Choose a reason for hiding this comment

shen390s commented Apr 24, 2024

shen390s commented Apr 26, 2024

namhyung commented Apr 26, 2024

paranlee commented May 9, 2024 • edited Loading

shen390s commented Feb 5, 2024 •

edited

Loading

namhyung commented Mar 20, 2024 •

edited

Loading

shen390s commented Apr 11, 2024 •

edited

Loading

shen390s commented Apr 12, 2024 •

edited

Loading

namhyung commented Apr 12, 2024 •

edited

Loading

paranlee commented May 9, 2024 •

edited

Loading