|
DEBUG1 - 10:52:58.974811542 [15415/15415]: [sessiond configuration]
|
|
DEBUG1 - 10:52:58.974861290 [15415/15415]: verbose: 3
|
|
DEBUG1 - 10:52:58.974865403 [15415/15415]: verbose consumer: 1
|
|
DEBUG1 - 10:52:58.974868786 [15415/15415]: quiet mode: False
|
|
DEBUG1 - 10:52:58.974872760 [15415/15415]: agent_tcp_port: [5345, 5354]
|
|
DEBUG1 - 10:52:58.974877459 [15415/15415]: application socket timeout: 5
|
|
DEBUG1 - 10:52:58.974881755 [15415/15415]: no-kernel: True
|
|
DEBUG1 - 10:52:58.974886374 [15415/15415]: background: False
|
|
DEBUG1 - 10:52:58.974889519 [15415/15415]: daemonize: False
|
|
DEBUG1 - 10:52:58.974892463 [15415/15415]: signal parent on start: False
|
|
DEBUG1 - 10:52:58.974895361 [15415/15415]: tracing group name: tracing
|
|
DEBUG1 - 10:52:58.974898415 [15415/15415]: kmod_probe_list: None
|
|
DEBUG1 - 10:52:58.974901427 [15415/15415]: kmod_extra_probe_list: None
|
|
DEBUG1 - 10:52:58.974904392 [15415/15415]: rundir: /var/lib/log/lttng_home/.lttng
|
|
DEBUG1 - 10:52:58.974907434 [15415/15415]: application socket path: /var/lib/log/lttng_home/.lttng/lttng-ust-sock-7
|
|
DEBUG1 - 10:52:58.974910493 [15415/15415]: client socket path: /var/lib/log/lttng_home/.lttng/client-lttng-sessiond
|
|
DEBUG1 - 10:52:58.974913487 [15415/15415]: wait shm path: /lttng-ust-wait-7-1000
|
|
DEBUG1 - 10:52:58.974916433 [15415/15415]: health socket path: /var/lib/log/lttng_home/.lttng/sessiond-health
|
|
DEBUG1 - 10:52:58.974919392 [15415/15415]: LTTNG_UST_CLOCK_PLUGIN: None
|
|
DEBUG1 - 10:52:58.974922247 [15415/15415]: pid file path: /var/lib/log/lttng_home/.lttng/lttng-sessiond.pid
|
|
DEBUG1 - 10:52:58.974925306 [15415/15415]: lock file path: /var/lib/log/lttng_home/.lttng/lttng-sessiond.lck
|
|
DEBUG1 - 10:52:58.974928228 [15415/15415]: session load path: None
|
|
DEBUG1 - 10:52:58.974932894 [15415/15415]: agent port file path: /var/lib/log/lttng_home/.lttng/agent.port
|
|
DEBUG3 - 10:52:58.974936170 [15415/15415]: Creating LTTng run directory: /var/lib/log/lttng_home/.lttng (in create_lttng_rundir() at main.c:5264)
|
|
DEBUG1 - 10:52:58.975407841 [15418/15418]: Resetting run_as worker signal handlers to default (in reset_sighandler() at runas.c:536)
|
|
DEBUG1 - 10:52:58.975518198 [15418/15418]: run_as signal handler set for SIGTERM and SIGINT (in set_worker_sighandlers() at runas.c:597)
|
|
DEBUG1 - 10:52:58.975578307 [15415/15415]: Health check time delta in seconds set to 20 (in health_init() at health.c:73)
|
|
DEBUG1 - 10:52:58.975663201 [15415/15419]: [ht-thread] startup. (in thread_ht_cleanup() at ht-cleanup.c:101)
|
|
DEBUG1 - 10:52:58.975709071 [15415/15419]: epoll set max size is 80958648 (in compat_epoll_set_max_size() at compat-epoll.c:337)
|
|
DEBUG3 - 10:52:58.975728226 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:52:58.976682273 [15415/15415]: Created hashtable size 4 at 0x22b5890 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:52:58.976695900 [15415/15415]: Created hashtable size 4 at 0x22b5c70 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:52:58.976700337 [15415/15415]: Created hashtable size 4 at 0x22b6030 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:52:58.976705947 [15415/15415]: Created hashtable size 4 at 0x22b63f0 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG2 - 10:52:58.976713520 [15415/15415]: Creating consumer directory: /var/lib/log/lttng_home/.lttng/ustconsumerd64 (in set_consumer_sockets() at main.c:5306)
|
|
DEBUG2 - 10:52:58.976780300 [15415/15415]: Creating consumer directory: /var/lib/log/lttng_home/.lttng/ustconsumerd32 (in set_consumer_sockets() at main.c:5306)
|
|
DEBUG3 - 10:52:58.976875774 [15415/15415]: Session daemon client socket 18 and application socket 19 created (in init_daemon_socket() at main.c:5133)
|
|
DEBUG3 - 10:52:58.976899267 [15415/15415]: Created hashtable size 4 at 0x22b67b0 of type 2 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:52:58.976904566 [15415/15415]: Global buffer per UID registry initialized (in buffer_reg_init_uid_registry() at buffer-registry.c:99)
|
|
DEBUG3 - 10:52:58.976911779 [15415/15415]: Created hashtable size 4 at 0x22b6b70 of type 2 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:52:58.976915074 [15415/15415]: Global buffer per PID registry initialized (in buffer_reg_init_pid_registry() at buffer-registry.c:228)
|
|
DEBUG1 - 10:52:58.976919914 [15415/15415]: Command subsystem initialized (in cmd_init() at cmd.c:4149)
|
|
DEBUG1 - 10:52:58.977020574 [15415/15415]: Pid 15415 written in file /var/lib/log/lttng_home/.lttng/lttng-sessiond.pid (in utils_create_pid_file() at utils.c:507)
|
|
DEBUG1 - 10:52:58.977052949 [15415/15415]: TCP inet operation timeout set to 180 sec (in lttcomm_inet_init() at inet.c:546)
|
|
DEBUG1 - 10:52:58.977099297 [15415/15421]: [thread] Manage health check started (in thread_manage_health() at main.c:4070)
|
|
DEBUG1 - 10:52:58.977136631 [15415/15422]: [notification-thread] Started notification thread (in thread_notification() at notification-thread.c:482)
|
|
DEBUG1 - 10:52:58.977160426 [15415/15423]: [thread] Manage client started (in thread_manage_clients() at main.c:4261)
|
|
DEBUG1 - 10:52:58.977208609 [15415/15424]: [thread] Dispatch UST command started (in thread_dispatch_ust_registration() at main.c:1757)
|
|
DEBUG1 - 10:52:58.977177580 [15415/15422]: [notification-thread] Creating notification channel UNIX socket at /var/lib/log/lttng_home/.lttng/sessiond-notification (in notification_channel_socket_create() at notification-thread.c:221)
|
|
DEBUG1 - 10:52:58.977663841 [15415/15426]: [thread] Manage application started (in thread_manage_apps() at main.c:1443)
|
|
DEBUG1 - 10:52:58.977640375 [15415/15425]: [thread] Manage application registration started (in thread_registration_apps() at main.c:2002)
|
|
DEBUG1 - 10:52:58.977703594 [15415/15422]: [notification-thread] Notification channel UNIX socket created (fd = 29) (in notification_channel_socket_create() at notification-thread.c:248)
|
|
DEBUG1 - 10:52:58.977710042 [15415/15426]: Apps thread polling (in thread_manage_apps() at main.c:1473)
|
|
DEBUG1 - 10:52:58.977653518 [15415/15424]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
|
|
DEBUG1 - 10:52:58.977638462 [15415/15421]: Health check ready (in thread_manage_health() at main.c:4132)
|
|
DEBUG1 - 10:52:58.977721666 [15415/15424]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1784)
|
|
DEBUG1 - 10:52:58.977724507 [15415/15425]: Notifying applications of session daemon state: 1 (in notify_ust_apps() at main.c:661)
|
|
DEBUG1 - 10:52:58.977728140 [15415/15422]: [notification-thread] Listening on notification channel socket (in init_thread_state() at notification-thread.c:387)
|
|
DEBUG1 - 10:52:58.977702498 [15415/15427]: [ust-thread] Manage application notify command (in ust_thread_manage_notify() at ust-thread.c:40)
|
|
DEBUG1 - 10:52:58.977734696 [15415/15429]: [load-session-thread] Load session (in thread_load_session() at load-session-thread.c:91)
|
|
DEBUG3 - 10:52:58.977764232 [15415/15427]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
|
|
DEBUG1 - 10:52:58.977737111 [15415/15428]: [agent-thread] Manage agent application registration. (in agent_thread_manage_registration() at agent-thread.c:300)
|
|
DEBUG1 - 10:52:58.977744698 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:52:58.977785582 [15415/15425]: Got the wait shm fd 34 (in get_wait_shm() at shm.c:115)
|
|
DEBUG3 - 10:52:58.977793557 [15415/15428]: URI string: tcp://localhost (in uri_parse() at uri.c:324)
|
|
DEBUG1 - 10:52:58.977827479 [15415/15425]: Futex wait update active 1 (in futex_wait_update() at futex.c:65)
|
|
DEBUG1 - 10:52:58.977832838 [15415/15425]: Accepting application registration (in thread_registration_apps() at main.c:2039)
|
|
DEBUG1 - 10:53:01.498231860 [15415/15425]: UST registration received with pid:7495 ppid:1 uid:1000 gid:1000 sock:36 name:mysqld-ust (version 7.2) (in thread_registration_apps() at main.c:2155)
|
|
DEBUG1 - 10:53:01.498254136 [15415/15425]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
|
|
DEBUG1 - 10:53:01.498258397 [15415/15425]: Accepting application registration (in thread_registration_apps() at main.c:2039)
|
|
DEBUG1 - 10:53:01.498258805 [15415/15424]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105)
|
|
DEBUG1 - 10:53:01.498269214 [15415/15424]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
|
|
DEBUG1 - 10:53:01.498272077 [15415/15425]: UST registration received with pid:7495 ppid:1 uid:1000 gid:1000 sock:37 name:mysqld-ust (version 7.2) (in thread_registration_apps() at main.c:2155)
|
|
DEBUG1 - 10:53:01.498273638 [15415/15424]: Dispatching UST registration pid:7495 ppid:1 uid:1000 gid:1000 sock:36 name:mysqld-ust (version 7.2) (in thread_dispatch_ust_registration() at main.c:1796)
|
|
DEBUG1 - 10:53:01.498279512 [15415/15425]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
|
|
DEBUG1 - 10:53:01.498283022 [15415/15425]: Accepting application registration (in thread_registration_apps() at main.c:2039)
|
|
DEBUG3 - 10:53:01.498286136 [15415/15424]: UST app creating application for socket 36 (in ust_app_create() at ust-app.c:3365)
|
|
DEBUG1 - 10:53:01.498299902 [15415/15425]: UST registration received with pid:14173 ppid:1 uid:1000 gid:1000 sock:38 name:pbs-ust (version 7.2) (in thread_registration_apps() at main.c:2155)
|
|
DEBUG1 - 10:53:01.498304160 [15415/15425]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
|
|
DEBUG1 - 10:53:01.498307093 [15415/15425]: Accepting application registration (in thread_registration_apps() at main.c:2039)
|
|
DEBUG3 - 10:53:01.498311311 [15415/15424]: Created hashtable size 4 at 0x22c35e0 of type 2 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG1 - 10:53:01.498319474 [15415/15425]: UST registration received with pid:14173 ppid:1 uid:1000 gid:1000 sock:39 name:pbs-ust (version 7.2) (in thread_registration_apps() at main.c:2155)
|
|
DEBUG3 - 10:53:01.498322531 [15415/15424]: Created hashtable size 4 at 0x22f15e0 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG1 - 10:53:01.498323498 [15415/15425]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
|
|
DEBUG1 - 10:53:01.498343004 [15415/15425]: Accepting application registration (in thread_registration_apps() at main.c:2039)
|
|
DEBUG3 - 10:53:01.498334163 [15415/15424]: Created hashtable size 4 at 0x22ca020 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG1 - 10:53:01.498383475 [15415/15424]: Dispatching UST registration pid:7495 ppid:1 uid:1000 gid:1000 sock:37 name:mysqld-ust (version 7.2) (in thread_dispatch_ust_registration() at main.c:1796)
|
|
DEBUG3 - 10:53:01.498390068 [15415/15424]: UST app notify socket 37 is set (in thread_dispatch_ust_registration() at main.c:1853)
|
|
DEBUG1 - 10:53:01.498410094 [15415/15424]: App registered with pid:7495 ppid:1 uid:1000 gid:1000 sock:36 name:mysqld-ust notify_sock:37 (version 7.2) (in ust_app_add() at ust-app.c:3454)
|
|
DEBUG3 - 10:53:01.498477364 [15415/15427]: [ust-thread] Manage notify return from poll on 2 fds (in ust_thread_manage_notify() at ust-thread.c:76)
|
|
DEBUG3 - 10:53:01.498496652 [15415/15427]: UST thread notify added sock 37 to pollset (in ust_thread_manage_notify() at ust-thread.c:137)
|
|
DEBUG3 - 10:53:01.498500806 [15415/15427]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
|
|
DEBUG1 - 10:53:01.498509195 [15415/15424]: Dispatching UST registration pid:14173 ppid:1 uid:1000 gid:1000 sock:38 name:pbs-ust (version 7.2) (in thread_dispatch_ust_registration() at main.c:1796)
|
|
DEBUG3 - 10:53:01.498515973 [15415/15424]: UST app creating application for socket 38 (in ust_app_create() at ust-app.c:3365)
|
|
DEBUG1 - 10:53:01.498514319 [15415/15426]: Apps thread return from poll on 2 fds (in thread_manage_apps() at main.c:1480)
|
|
DEBUG3 - 10:53:01.498522227 [15415/15424]: Created hashtable size 4 at 0x22b7fb0 of type 2 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:01.498530206 [15415/15424]: Created hashtable size 4 at 0x22c1740 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG1 - 10:53:01.498531414 [15415/15426]: Apps with sock 36 added to poll set (in thread_manage_apps() at main.c:1537)
|
|
DEBUG3 - 10:53:01.498534658 [15415/15424]: Created hashtable size 4 at 0x22c5fa0 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG1 - 10:53:01.498535709 [15415/15426]: Apps thread polling (in thread_manage_apps() at main.c:1473)
|
|
DEBUG1 - 10:53:01.498549435 [15415/15424]: Dispatching UST registration pid:14173 ppid:1 uid:1000 gid:1000 sock:39 name:pbs-ust (version 7.2) (in thread_dispatch_ust_registration() at main.c:1796)
|
|
DEBUG3 - 10:53:01.498553577 [15415/15424]: UST app notify socket 39 is set (in thread_dispatch_ust_registration() at main.c:1853)
|
|
DEBUG1 - 10:53:01.498557778 [15415/15424]: App registered with pid:14173 ppid:1 uid:1000 gid:1000 sock:38 name:pbs-ust notify_sock:39 (version 7.2) (in ust_app_add() at ust-app.c:3454)
|
|
DEBUG3 - 10:53:01.498591709 [15415/15427]: [ust-thread] Manage notify return from poll on 3 fds (in ust_thread_manage_notify() at ust-thread.c:76)
|
|
DEBUG3 - 10:53:01.498601739 [15415/15427]: UST thread notify added sock 39 to pollset (in ust_thread_manage_notify() at ust-thread.c:137)
|
|
DEBUG3 - 10:53:01.498605057 [15415/15427]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
|
|
DEBUG1 - 10:53:01.498611519 [15415/15424]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1784)
|
|
DEBUG1 - 10:53:01.498615642 [15415/15424]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105)
|
|
DEBUG1 - 10:53:01.498614849 [15415/15426]: Apps thread return from poll on 3 fds (in thread_manage_apps() at main.c:1480)
|
|
DEBUG1 - 10:53:01.498620458 [15415/15424]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
|
|
DEBUG1 - 10:53:01.498631440 [15415/15426]: Apps with sock 38 added to poll set (in thread_manage_apps() at main.c:1537)
|
|
DEBUG1 - 10:53:01.498632735 [15415/15424]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1784)
|
|
DEBUG1 - 10:53:01.498636652 [15415/15426]: Apps thread polling (in thread_manage_apps() at main.c:1473)
|
|
DEBUG1 - 10:53:02.784134934 [15415/15425]: UST registration received with pid:15014 ppid:8052 uid:1000 gid:1000 sock:41 name:hello-ust (version 7.2) (in thread_registration_apps() at main.c:2155)
|
|
DEBUG1 - 10:53:02.784162510 [15415/15425]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
|
|
DEBUG1 - 10:53:02.784168505 [15415/15425]: Accepting application registration (in thread_registration_apps() at main.c:2039)
|
|
DEBUG1 - 10:53:02.784170926 [15415/15424]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105)
|
|
DEBUG1 - 10:53:02.784187055 [15415/15424]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
|
|
DEBUG1 - 10:53:02.784187088 [15415/15425]: UST registration received with pid:15014 ppid:8052 uid:1000 gid:1000 sock:42 name:hello-ust (version 7.2) (in thread_registration_apps() at main.c:2155)
|
|
DEBUG1 - 10:53:02.784195102 [15415/15424]: Dispatching UST registration pid:15014 ppid:8052 uid:1000 gid:1000 sock:41 name:hello-ust (version 7.2) (in thread_dispatch_ust_registration() at main.c:1796)
|
|
DEBUG1 - 10:53:02.784200182 [15415/15425]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
|
|
DEBUG3 - 10:53:02.784201542 [15415/15424]: UST app creating application for socket 41 (in ust_app_create() at ust-app.c:3365)
|
|
DEBUG1 - 10:53:02.784205786 [15415/15425]: Accepting application registration (in thread_registration_apps() at main.c:2039)
|
|
DEBUG3 - 10:53:02.784215472 [15415/15424]: Created hashtable size 4 at 0x22c79f0 of type 2 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:02.784223033 [15415/15424]: Created hashtable size 4 at 0x22c7d20 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:02.784230295 [15415/15424]: Created hashtable size 4 at 0x22c8050 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG1 - 10:53:02.784248865 [15415/15424]: Dispatching UST registration pid:15014 ppid:8052 uid:1000 gid:1000 sock:42 name:hello-ust (version 7.2) (in thread_dispatch_ust_registration() at main.c:1796)
|
|
DEBUG3 - 10:53:02.784253132 [15415/15424]: UST app notify socket 42 is set (in thread_dispatch_ust_registration() at main.c:1853)
|
|
DEBUG1 - 10:53:02.784259915 [15415/15424]: App registered with pid:15014 ppid:8052 uid:1000 gid:1000 sock:41 name:hello-ust notify_sock:42 (version 7.2) (in ust_app_add() at ust-app.c:3454)
|
|
DEBUG3 - 10:53:02.784342016 [15415/15427]: [ust-thread] Manage notify return from poll on 4 fds (in ust_thread_manage_notify() at ust-thread.c:76)
|
|
DEBUG3 - 10:53:02.784376335 [15415/15427]: UST thread notify added sock 42 to pollset (in ust_thread_manage_notify() at ust-thread.c:137)
|
|
DEBUG3 - 10:53:02.784381234 [15415/15427]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
|
|
DEBUG1 - 10:53:02.784396484 [15415/15424]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1784)
|
|
DEBUG1 - 10:53:02.784400619 [15415/15426]: Apps thread return from poll on 4 fds (in thread_manage_apps() at main.c:1480)
|
|
DEBUG1 - 10:53:02.784404176 [15415/15424]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105)
|
|
DEBUG1 - 10:53:02.784421145 [15415/15424]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
|
|
DEBUG1 - 10:53:02.784425163 [15415/15424]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1784)
|
|
DEBUG1 - 10:53:02.784424981 [15415/15426]: Apps with sock 41 added to poll set (in thread_manage_apps() at main.c:1537)
|
|
DEBUG1 - 10:53:02.784441684 [15415/15426]: Apps thread polling (in thread_manage_apps() at main.c:1473)
|
|
DEBUG2 - 10:53:04.983895991 [15415/15428]: IP address resolved to 127.0.0.1 (in set_ip_address() at uri.c:165)
|
|
DEBUG3 - 10:53:04.983911227 [15415/15428]: URI dtype: 1, proto: 1, host: localhost, subdir: , ctrl: 0, data: 0 (in uri_parse() at uri.c:538)
|
|
DEBUG3 - 10:53:04.983927654 [15415/15428]: [agent-thread] Trying to bind on port 5345 (in init_tcp_socket() at agent-thread.c:118)
|
|
DEBUG1 - 10:53:04.983939496 [15415/15428]: [agent-thread] Listening on TCP port 5345 and socket 34 (in init_tcp_socket() at agent-thread.c:155)
|
|
DEBUG1 - 10:53:04.984057240 [15415/15428]: Pid 5345 written in file /var/lib/log/lttng_home/.lttng/agent.port (in utils_create_pid_file() at utils.c:507)
|
|
DEBUG3 - 10:53:04.984070594 [15415/15428]: [agent-thread] Manage agent polling (in agent_thread_manage_registration() at agent-thread.c:348)
|
|
DEBUG1 - 10:53:04.984531782 [15415/15423]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
|
|
DEBUG1 - 10:53:24.060259197 [15415/15423]: Wait for client response (in thread_manage_clients() at main.c:4389)
|
|
DEBUG1 - 10:53:24.060389882 [15415/15423]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
|
|
DEBUG1 - 10:53:24.060402922 [15415/15423]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:4438)
|
|
DEBUG1 - 10:53:24.060416606 [15415/15423]: Clean command context structure (in clean_command_ctx() at main.c:641)
|
|
DEBUG1 - 10:53:24.060423008 [15415/15423]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
|
|
DEBUG1 - 10:53:24.060431029 [15415/15423]: Wait for client response (in thread_manage_clients() at main.c:4389)
|
|
DEBUG1 - 10:53:24.060443560 [15415/15423]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
|
|
DEBUG1 - 10:53:24.060461327 [15415/15423]: Processing client command 8 (in process_client_msg() at main.c:2877)
|
|
DEBUG1 - 10:53:24.060475390 [15415/15423]: Waiting for 1 URIs from client ... (in process_client_msg() at main.c:3660)
|
|
DEBUG2 - 10:53:24.060486780 [15415/15423]: Trying to find session by name auto-20200115-105324 (in session_find_by_name() at session.c:276)
|
|
DEBUG3 - 10:53:24.060510674 [15415/15423]: Created hashtable size 4 at 0x22c2b60 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG1 - 10:53:24.060515216 [15415/15423]: Allocating ltt_sessions_ht_by_id (in ltt_sessions_ht_alloc() at session.c:153)
|
|
DEBUG3 - 10:53:24.060519520 [15415/15423]: Created hashtable size 4 at 0x22c3300 of type 2 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG1 - 10:53:24.060524464 [15415/15423]: Tracing session auto-20200115-105324 created with ID 0 by UID 1000 GID 1000 (in session_create() at session.c:420)
|
|
DEBUG2 - 10:53:24.060528522 [15415/15423]: Trying to find session by name auto-20200115-105324 (in session_find_by_name() at session.c:276)
|
|
DEBUG3 - 10:53:24.060537716 [15415/15423]: Created hashtable size 4 at 0x22ee980 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG2 - 10:53:24.060543284 [15415/15423]: Setting trace directory path from URI to /var/lib/log/lttng_home/lttng-traces/auto-20200115-105324 (in add_uri_to_consumer() at cmd.c:787)
|
|
DEBUG1 - 10:53:24.060556318 [15415/15423]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
|
|
DEBUG1 - 10:53:24.060571488 [15415/15423]: Clean command context structure (in clean_command_ctx() at main.c:641)
|
|
DEBUG1 - 10:53:24.060575386 [15415/15423]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
|
|
DEBUG1 - 10:53:33.242939252 [15415/15423]: Wait for client response (in thread_manage_clients() at main.c:4389)
|
|
DEBUG1 - 10:53:33.242991422 [15415/15423]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
|
|
DEBUG1 - 10:53:33.243012873 [15415/15423]: Processing client command 6 (in process_client_msg() at main.c:2877)
|
|
DEBUG1 - 10:53:33.243026714 [15415/15423]: Getting session auto-20200115-105324 by name (in process_client_msg() at main.c:2970)
|
|
DEBUG2 - 10:53:33.243034052 [15415/15423]: Trying to find session by name auto-20200115-105324 (in session_find_by_name() at session.c:276)
|
|
DEBUG1 - 10:53:33.243043405 [15415/15423]: Creating UST session (in create_ust_session() at main.c:2748)
|
|
DEBUG3 - 10:53:33.243062613 [15415/15423]: Created hashtable size 4 at 0x22ee070 of type 0 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:33.243077079 [15415/15423]: Created hashtable size 4 at 0x22edc60 of type 2 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:33.243091260 [15415/15423]: Created hashtable size 4 at 0x22ed210 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG2 - 10:53:33.243101924 [15415/15423]: UST trace session create successful (in trace_ust_create_session() at trace-ust.c:320)
|
|
DEBUG3 - 10:53:33.243119052 [15415/15423]: Copying tracing session consumer output in UST session (in copy_session_consumer() at main.c:2695)
|
|
DEBUG3 - 10:53:33.243160891 [15415/15423]: Created hashtable size 4 at 0x22eed90 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:33.243159411 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:53:33.243183237 [15415/15423]: Copy session consumer subdir /ust (in copy_session_consumer() at main.c:2713)
|
|
DEBUG1 - 10:53:33.243192268 [15415/15423]: Spawning consumerd (in spawn_consumerd() at main.c:2379)
|
|
DEBUG2 - 10:53:33.243590043 [15415/15423]: Consumer pid 16083 (in start_consumerd() at main.c:2556)
|
|
DEBUG2 - 10:53:33.243627967 [15415/15423]: Spawning consumer control thread (in start_consumerd() at main.c:2559)
|
|
DEBUG1 - 10:53:33.244090045 [16083/16083]: Using 64-bit UST consumer at: /usr/lib64/lttng/libexec/lttng-consumerd (in spawn_consumerd() at main.c:2457)
|
|
DEBUG1 - 10:53:33.244155505 [15415/16084]: [thread] Manage consumer started (in thread_manage_consumer() at main.c:1085)
|
|
DEBUG1 - 10:53:33.245516418 [16083/16083]: Health check time delta in seconds set to 20 (in health_init() at health.c:73)
|
|
DEBUG1 - 10:53:33.246886278 [16083/16083]: TCP inet operation timeout set to 180 sec (in lttcomm_inet_init() at inet.c:546)
|
|
DEBUG1 - 10:53:33.247061621 [16086/16086]: Resetting run_as worker signal handlers to default (in reset_sighandler() at runas.c:536)
|
|
DEBUG1 - 10:53:33.247171989 [16086/16086]: run_as signal handler set for SIGTERM and SIGINT (in set_worker_sighandlers() at runas.c:597)
|
|
DEBUG1 - 10:53:33.247254645 [16083/16083]: Connecting to error socket /var/lib/log/lttng_home/.lttng/ustconsumerd64/error (in main() at lttng-consumerd.c:464)
|
|
DEBUG2 - 10:53:33.247299035 [15415/16084]: Receiving code from consumer err_sock (in thread_manage_consumer() at main.c:1183)
|
|
DEBUG1 - 10:53:33.247341678 [16083/16087]: [thread] Manage health check started (in thread_manage_health() at health-consumerd.c:167)
|
|
DEBUG1 - 10:53:33.247448515 [16083/16087]: epoll set max size is 80958648 (in compat_epoll_set_max_size() at compat-epoll.c:337)
|
|
DEBUG1 - 10:53:33.247475257 [16083/16087]: Health check ready (in thread_manage_health() at health-consumerd.c:240)
|
|
DEBUG3 - 10:53:33.253277273 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG1 - 10:53:33.347449593 [16083/16089]: Thread channel poll started (in consumer_thread_channel_poll() at consumer.c:2855)
|
|
DEBUG1 - 10:53:33.347464099 [16083/16090]: Thread metadata poll started (in consumer_thread_metadata_poll() at consumer.c:2259)
|
|
DEBUG1 - 10:53:33.347492934 [16083/16091]: Updating poll fd array (in update_poll_array() at consumer.c:1091)
|
|
DEBUG1 - 10:53:33.347492896 [16083/16089]: Channel main loop started (in consumer_thread_channel_poll() at consumer.c:2870)
|
|
DEBUG1 - 10:53:33.347521180 [16083/16091]: polling on 2 fd (in consumer_thread_data_poll() at consumer.c:2544)
|
|
DEBUG1 - 10:53:33.347508734 [16083/16090]: Metadata main loop started (in consumer_thread_metadata_poll() at consumer.c:2275)
|
|
DEBUG1 - 10:53:33.347506583 [16083/16092]: Creating command socket /var/lib/log/lttng_home/.lttng/ustconsumerd64/command (in consumer_thread_sessiond_poll() at consumer.c:3123)
|
|
DEBUG1 - 10:53:33.347525998 [16083/16089]: Channel poll wait (in consumer_thread_channel_poll() at consumer.c:2875)
|
|
DEBUG1 - 10:53:33.347533231 [16083/16090]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2281)
|
|
DEBUG1 - 10:53:33.347589069 [16083/16092]: Sending ready command to lttng-sessiond (in consumer_thread_sessiond_poll() at consumer.c:3136)
|
|
DEBUG1 - 10:53:33.347632546 [16083/16092]: Connection on client_socket (in consumer_thread_sessiond_poll() at consumer.c:3158)
|
|
DEBUG1 - 10:53:33.347644927 [16083/16092]: Metadata connection on client_socket (in set_metadata_socket() at consumer.c:3084)
|
|
DEBUG1 - 10:53:33.347644616 [15415/16084]: Consumer command socket ready (fd: 45 (in thread_manage_consumer() at main.c:1223)
|
|
DEBUG1 - 10:53:33.347653958 [15415/16084]: Consumer metadata socket ready (fd: 46) (in thread_manage_consumer() at main.c:1225)
|
|
DEBUG3 - 10:53:33.347676433 [15415/16084]: Sending set_channel_monitor_pipe command to consumer (in consumer_send_channel_monitor_pipe() at consumer.c:1078)
|
|
DEBUG1 - 10:53:33.347700264 [16083/16092]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
|
|
DEBUG3 - 10:53:33.347727488 [15415/16084]: Sending channel monitoring pipe 14 to consumer on socket 45 (in consumer_send_channel_monitor_pipe() at consumer.c:1085)
|
|
DEBUG1 - 10:53:33.347753728 [16083/16092]: Received channel monitor pipe (27) (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1899)
|
|
DEBUG1 - 10:53:33.347766664 [16083/16092]: Channel monitor pipe set as non-blocking (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1920)
|
|
DEBUG1 - 10:53:33.347773271 [16083/16092]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
|
|
DEBUG2 - 10:53:33.347775788 [15415/16084]: Channel monitoring pipe successfully sent (in consumer_send_channel_monitor_pipe() at consumer.c:1091)
|
|
DEBUG3 - 10:53:33.347846221 [15415/15423]: Consumer socket created (fd: 45) and added to output (in consumer_create_socket() at consumer.c:301)
|
|
DEBUG1 - 10:53:33.347864638 [15415/15423]: Setting relayd for session auto-20200115-105324 (in cmd_setup_relayd() at cmd.c:1043)
|
|
DEBUG1 - 10:53:33.347879760 [15415/15423]: Enable event command for event 'hello_world:my_first_tracepoint' (in _cmd_enable_event() at cmd.c:1864)
|
|
DEBUG2 - 10:53:33.347889634 [15415/15423]: Trace UST channel channel0 not found by name (in trace_ust_find_channel_by_name() at trace-ust.c:196)
|
|
DEBUG1 - 10:53:33.347914186 [15415/15423]: Enabling channel for session auto-20200115-105324 (in cmd_enable_channel() at cmd.c:1346)
|
|
DEBUG2 - 10:53:33.347924873 [15415/15423]: Trace UST channel channel0 not found by name (in trace_ust_find_channel_by_name() at trace-ust.c:196)
|
|
DEBUG3 - 10:53:33.347939033 [15415/15423]: Created hashtable size 4 at 0x22c7620 of type 0 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:33.347948094 [15415/15423]: Created hashtable size 4 at 0x22ef190 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG2 - 10:53:33.347952961 [15415/15423]: Trace UST channel channel0 created (in trace_ust_create_channel() at trace-ust.c:395)
|
|
DEBUG2 - 10:53:33.347959625 [15415/15423]: Channel channel0 is being created for UST with buffer 1 and id 0 (in channel_ust_create() at channel.c:455)
|
|
DEBUG2 - 10:53:33.347967388 [15415/15423]: UST app adding channel channel0 to UST domain for session id 0 (in ust_app_create_channel_glb() at ust-app.c:4144)
|
|
DEBUG2 - 10:53:33.347979846 [15415/15423]: UST app pid: 14173 session id 0 not found, creating it (in create_ust_app_session() at ust-app.c:2172)
|
|
DEBUG3 - 10:53:33.347999744 [15415/15423]: Created hashtable size 4 at 0x22c2e30 of type 0 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG2 - 10:53:33.348054024 [15415/15423]: Shadow copy of session handle -1 (in shadow_copy_session() at ust-app.c:1870)
|
|
DEBUG3 - 10:53:33.348083668 [15415/15423]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG3 - 10:53:33.348106029 [15415/15423]: Created hashtable size 4 at 0x22ecac0 of type 2 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:33.348111751 [15415/15423]: Buffer registry per UID created id: 0, ABI: 64, uid: 1000, domain: 2 (in buffer_reg_uid_create() at buffer-registry.c:152)
|
|
DEBUG3 - 10:53:33.348128270 [15415/15423]: Created hashtable size 4 at 0x22c07d0 of type 0 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:33.348135182 [15415/15423]: Created hashtable size 4 at 0x22c0b90 of type 2 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:33.348228512 [15415/15423]: Append to metadata: "/* CTF 1.8 */
|
|
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:33.348256458 [15415/15423]: Append to metadata: "typealias integer { size = 8; align = 8; signed = false; } := uint8_t;
|
|
typealias integer { size = 16; align = 8; signed = false; } := uint16_t;
|
|
typealias integer { size = 32; align = 8; signed = false; } := uint32_t;
|
|
typealias integer { size = 64; align = 8; signed = false; } := uint64_t;
|
|
typealias integer { size = 64; align = 8; signed = false; } := unsigned long;
|
|
typealias integer { size = 5; align = 1; signed = false; } := uint5_t;
|
|
typealias integer { size = 27; align = 1; signed = false; } := uint27_t;
|
|
|
|
trace {
|
|
major = 1;
|
|
minor = 8;
|
|
uuid = "49322b1a-7136-4980-b4fb-d72955c4156b";
|
|
byte_order = le;
|
|
packet.header := struct {
|
|
uint32_t magic;
|
|
uint8_t uuid[16];
|
|
uint32_t stream_id;
|
|
uint64_t stream_instance_id;
|
|
};
|
|
};
|
|
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:33.348268520 [15415/15423]: Append to metadata: "env {
|
|
hostname = "localhost.localdomain";
|
|
domain = "ust";
|
|
tracer_name = "lttng-ust";
|
|
tracer_major = 2;
|
|
tracer_minor = 10;
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:33.348274276 [15415/15423]: Append to metadata: "};
|
|
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:33.348279812 [15415/15423]: Append to metadata: "clock {
|
|
name = "monotonic";
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:33.348339635 [15415/15423]: Append to metadata: " uuid = "9d841637-e629-4139-a042-b3f2f0d11d7e";
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:33.348360466 [15415/15423]: Append to metadata: " description = "Monotonic Clock";
|
|
freq = 1000000000; /* Frequency, in Hz */
|
|
/* clock value offset from Epoch is: offset * (1/freq) */
|
|
offset = 1578471293467343157;
|
|
};
|
|
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:33.348373551 [15415/15423]: Append to metadata: "typealias integer {
|
|
size = 27; align = 1; signed = false;
|
|
map = clock.monotonic.value;
|
|
} := uint27_clock_monotonic_t;
|
|
|
|
typealias integer {
|
|
size = 32; align = 8; signed = false;
|
|
map = clock.monotonic.value;
|
|
} := uint32_clock_monotonic_t;
|
|
|
|
typealias integer {
|
|
size = 64; align = 8; signed = false;
|
|
map = clock.monotonic.value;
|
|
} := uint64_clock_monotonic_t;
|
|
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:33.348383156 [15415/15423]: Append to metadata: "struct packet_context {
|
|
uint64_clock_monotonic_t timestamp_begin;
|
|
uint64_clock_monotonic_t timestamp_end;
|
|
uint64_t content_size;
|
|
uint64_t packet_size;
|
|
uint64_t packet_seq_num;
|
|
unsigned long events_discarded;
|
|
uint32_t cpu_id;
|
|
};
|
|
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:33.348397265 [15415/15423]: Append to metadata: "struct event_header_compact {
|
|
enum : uint5_t { compact = 0 ... 30, extended = 31 } id;
|
|
variant <id> {
|
|
struct {
|
|
uint27_clock_monotonic_t timestamp;
|
|
} compact;
|
|
struct {
|
|
uint32_t id;
|
|
uint64_clock_monotonic_t timestamp;
|
|
} extended;
|
|
} v;
|
|
} align(8);
|
|
|
|
struct event_header_large {
|
|
enum : uint16_t { compact = 0 ... 65534, extended = 65535 } id;
|
|
variant <id> {
|
|
struct {
|
|
uint32_clock_monotonic_t timestamp;
|
|
} compact;
|
|
struct {
|
|
uint32_t id;
|
|
uint64_clock_monotonic_t timestamp;
|
|
} extended;
|
|
} v;
|
|
} align(8);
|
|
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:33.348403440 [15415/15423]: Buffer registry per UID adding to global registry with id: 0 (in buffer_reg_uid_add() at buffer-registry.c:174)
|
|
DEBUG3 - 10:53:33.348410645 [15415/15423]: UST app buffer registry per UID created successfully (in setup_buffer_reg_uid() at ust-app.c:2135)
|
|
DEBUG2 - 10:53:33.348558352 [15415/15423]: UST app session created successfully with handle 4 (in create_ust_app_session() at ust-app.c:2247)
|
|
DEBUG3 - 10:53:33.348579823 [15415/15423]: Created hashtable size 4 at 0x22c3880 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:33.348588909 [15415/15423]: Created hashtable size 4 at 0x22c3c10 of type 0 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:33.348595579 [15415/15423]: UST app channel channel0 allocated (in alloc_ust_app_channel() at ust-app.c:1049)
|
|
DEBUG2 - 10:53:33.348602001 [15415/15423]: UST app shadow copy of channel channel0 started (in shadow_copy_channel() at ust-app.c:1792)
|
|
DEBUG3 - 10:53:33.348607024 [15415/15423]: UST app shadow copy of channel channel0 done (in shadow_copy_channel() at ust-app.c:1846)
|
|
DEBUG1 - 10:53:33.348613859 [15415/15423]: UST app creating channel channel0 with per UID buffers (in create_channel_per_uid() at ust-app.c:2864)
|
|
DEBUG3 - 10:53:33.348618691 [15415/15423]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG2 - 10:53:33.348624896 [15415/15423]: UST app creating buffer registry channel for channel0 (in create_buffer_reg_channel() at ust-app.c:2708)
|
|
DEBUG3 - 10:53:33.348629702 [15415/15423]: Buffer registry channel create with key: 0 (in buffer_reg_channel_create() at buffer-registry.c:380)
|
|
DEBUG3 - 10:53:33.348641539 [15415/15423]: Created hashtable size 4 at 0x22d2080 of type 0 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:33.348657675 [15415/15423]: Session 0 found by id. (in session_find_by_id() at session.c:312)
|
|
DEBUG2 - 10:53:33.348668378 [15415/15423]: Asking UST consumer for channel (in ask_channel_creation() at ust-consumer.c:121)
|
|
DEBUG3 - 10:53:33.348683365 [15415/15423]: mkdir() recursive /var/lib/log/lttng_home/lttng-traces/auto-20200115-105324/ust/uid/1000/64-bit with mode 504 for uid 1000 and gid 1000 (in run_as_mkdir_recursive() at runas.c:470)
|
|
DEBUG1 - 10:53:33.348703184 [15415/15423]: Using run_as worker (in run_as() at runas.c:450)
|
|
DEBUG3 - 10:53:33.348932237 [15415/15423]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:796)
|
|
DEBUG1 - 10:53:33.348953540 [16083/16092]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
|
|
DEBUG1 - 10:53:33.348975986 [16083/16092]: Allocated channel (key 1) (in consumer_allocate_channel() at consumer.c:1031)
|
|
DEBUG1 - 10:53:33.351916211 [16083/16092]: Using run_as worker (in run_as() at runas.c:450)
|
|
DEBUG1 - 10:53:33.352019081 [16083/16092]: Using run_as worker (in run_as() at runas.c:450)
|
|
DEBUG1 - 10:53:33.352093412 [16083/16092]: Using run_as worker (in run_as() at runas.c:450)
|
|
DEBUG1 - 10:53:33.352139216 [16083/16092]: utils_unlink_stream_file /var/lib/log/lttng_home/lttng-traces/auto-20200115-105324/ust/uid/1000/64-bit/index/channel0_0.idx returns -1 (in utils_unlink_stream_file() at utils.c:830)
|
|
DEBUG1 - 10:53:33.352155132 [16083/16092]: Using run_as worker (in run_as() at runas.c:450)
|
|
DEBUG1 - 10:53:33.352216478 [16083/16092]: UST consumer add stream channel0_0 (key: 35) with relayd id 0 (in create_ust_streams() at ust-consumer.c:347)
|
|
DEBUG1 - 10:53:33.352247021 [16083/16092]: UST consumer channel added (key: 1) (in add_channel() at ust-consumer.c:115)
|
|
DEBUG1 - 10:53:33.352250617 [16083/16089]: Channel poll return from wait with 1 fd(s) (in consumer_thread_channel_poll() at consumer.c:2879)
|
|
DEBUG1 - 10:53:33.352256188 [16083/16092]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
|
|
DEBUG1 - 10:53:33.352260079 [16083/16089]: Channel event caught in thread (in consumer_thread_channel_poll() at consumer.c:2881)
|
|
DEBUG1 - 10:53:33.352269066 [16083/16089]: Adding channel 32 to poll set (in consumer_thread_channel_poll() at consumer.c:2924)
|
|
DEBUG2 - 10:53:33.352264238 [15415/15423]: UST ask channel 1 successfully done with 1 stream(s) (in ask_channel_creation() at ust-consumer.c:218)
|
|
DEBUG1 - 10:53:33.352276112 [16083/16089]: Channel poll wait (in consumer_thread_channel_poll() at consumer.c:2875)
|
|
DEBUG1 - 10:53:33.352309744 [16083/16092]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
|
|
DEBUG1 - 10:53:33.352323063 [16083/16092]: UST consumer sending channel channel0 to sessiond (in send_sessiond_channel() at ust-consumer.c:562)
|
|
DEBUG1 - 10:53:33.352363464 [16083/16092]: UST consumer sending stream 35 to sessiond (in send_sessiond_stream() at ust-consumer.c:533)
|
|
DEBUG1 - 10:53:33.352376440 [16083/16092]: UST consumer NULL stream sent to sessiond (in send_sessiond_channel() at ust-consumer.c:626)
|
|
DEBUG2 - 10:53:33.352381462 [15415/15423]: UST app stream 1 received successfully (in ust_consumer_get_channel() at ust-consumer.c:339)
|
|
DEBUG1 - 10:53:33.352387804 [16083/16092]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
|
|
DEBUG1 - 10:53:33.352389775 [16083/16091]: poll num_rdy : 1 (in consumer_thread_data_poll() at consumer.c:2551)
|
|
DEBUG1 - 10:53:33.352397455 [16083/16091]: consumer_data_pipe wake up (in consumer_thread_data_poll() at consumer.c:2581)
|
|
DEBUG3 - 10:53:33.352399666 [15415/15423]: UST app consumer has no more stream available (in ust_consumer_get_channel() at ust-consumer.c:323)
|
|
DEBUG1 - 10:53:33.352404181 [16083/16091]: Updating poll fd array (in update_poll_array() at consumer.c:1091)
|
|
DEBUG1 - 10:53:33.352409333 [16083/16091]: polling on 3 fd (in consumer_thread_data_poll() at consumer.c:2544)
|
|
DEBUG2 - 10:53:33.352412042 [15415/15423]: UST app setup buffer registry channel for channel0 (in setup_buffer_reg_channel() at ust-app.c:2758)
|
|
DEBUG2 - 10:53:33.352419733 [15415/15423]: UST app setup buffer registry stream (in setup_buffer_reg_streams() at ust-app.c:2663)
|
|
DEBUG3 - 10:53:33.352426755 [15415/15423]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:410)
|
|
DEBUG3 - 10:53:33.352434626 [15415/15423]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:796)
|
|
DEBUG3 - 10:53:33.352439923 [15415/15423]: Session 0 found by id. (in session_find_by_id() at session.c:312)
|
|
DEBUG1 - 10:53:33.352456780 [15415/15423]: Beginning of waiter wait period (in lttng_waiter_wait() at waiter.c:58)
|
|
DEBUG1 - 10:53:33.352462987 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:33.352479309 [15415/15422]: [notification-thread] Handling fd (24) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:33.352488904 [15415/15422]: [notification-thread] Received add channel command (in handle_notification_thread_command() at notification-thread-events.c:1300)
|
|
DEBUG1 - 10:53:33.352494572 [15415/15422]: [notification-thread] Adding channel channel0 from session auto-20200115-105324, channel key = 1 in user space domain (in handle_notification_thread_command_add_channel() at notification-thread-events.c:812)
|
|
DEBUG1 - 10:53:33.352502974 [15415/15422]: [notification-thread] Found 0 triggers that apply to newly added channel (in handle_notification_thread_command_add_channel() at notification-thread-events.c:844)
|
|
DEBUG1 - 10:53:33.352515488 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:33.352521128 [15415/15423]: End of waiter wait period (in lttng_waiter_wait() at waiter.c:101)
|
|
DEBUG1 - 10:53:33.352527904 [15415/15423]: UST app sending buffer registry channel to ust sock 38 (in send_channel_uid_to_ust() at ust-app.c:2794)
|
|
DEBUG2 - 10:53:33.352539393 [15415/15423]: UST app send channel to sock 38 pid 14173 (name: channel0, key: 0) (in ust_consumer_send_channel_to_ust() at ust-consumer.c:445)
|
|
DEBUG2 - 10:53:33.352596641 [15415/15423]: UST consumer send stream to app 38 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:408)
|
|
DEBUG2 - 10:53:33.352658064 [15415/15423]: UST app create channel channel0 for PID 14173 completed (in create_ust_app_channel() at ust-app.c:3157)
|
|
DEBUG2 - 10:53:33.352671497 [15415/15423]: UST app pid: 7495 session id 0 not found, creating it (in create_ust_app_session() at ust-app.c:2172)
|
|
DEBUG3 - 10:53:33.352686824 [15415/15423]: Created hashtable size 4 at 0x22c1c00 of type 0 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG2 - 10:53:33.352701314 [15415/15423]: Shadow copy of session handle -1 (in shadow_copy_session() at ust-app.c:1870)
|
|
DEBUG3 - 10:53:33.352715197 [15415/15423]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG2 - 10:53:33.352833178 [15415/15423]: UST app session created successfully with handle 4 (in create_ust_app_session() at ust-app.c:2247)
|
|
DEBUG3 - 10:53:33.352844666 [15415/15423]: Created hashtable size 4 at 0x22c2130 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:33.352850853 [15415/15423]: Created hashtable size 4 at 0x22c24f0 of type 0 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:33.352855677 [15415/15423]: UST app channel channel0 allocated (in alloc_ust_app_channel() at ust-app.c:1049)
|
|
DEBUG2 - 10:53:33.352860548 [15415/15423]: UST app shadow copy of channel channel0 started (in shadow_copy_channel() at ust-app.c:1792)
|
|
DEBUG3 - 10:53:33.352866347 [15415/15423]: UST app shadow copy of channel channel0 done (in shadow_copy_channel() at ust-app.c:1846)
|
|
DEBUG1 - 10:53:33.352873134 [15415/15423]: UST app creating channel channel0 with per UID buffers (in create_channel_per_uid() at ust-app.c:2864)
|
|
DEBUG3 - 10:53:33.352880210 [15415/15423]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG1 - 10:53:33.352888084 [15415/15423]: UST app sending buffer registry channel to ust sock 36 (in send_channel_uid_to_ust() at ust-app.c:2794)
|
|
DEBUG2 - 10:53:33.352902085 [15415/15423]: UST app send channel to sock 36 pid 7495 (name: channel0, key: 0) (in ust_consumer_send_channel_to_ust() at ust-consumer.c:445)
|
|
DEBUG2 - 10:53:33.352957595 [15415/15423]: UST consumer send stream to app 36 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:408)
|
|
DEBUG2 - 10:53:33.353015250 [15415/15423]: UST app create channel channel0 for PID 7495 completed (in create_ust_app_channel() at ust-app.c:3157)
|
|
DEBUG2 - 10:53:33.353030052 [15415/15423]: UST app pid: 15014 session id 0 not found, creating it (in create_ust_app_session() at ust-app.c:2172)
|
|
DEBUG3 - 10:53:33.353048203 [15415/15423]: Created hashtable size 4 at 0x22bbad0 of type 0 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG2 - 10:53:33.353066208 [15415/15423]: Shadow copy of session handle -1 (in shadow_copy_session() at ust-app.c:1870)
|
|
DEBUG3 - 10:53:33.353072574 [15415/15423]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG2 - 10:53:33.353217295 [15415/15423]: UST app session created successfully with handle 1 (in create_ust_app_session() at ust-app.c:2247)
|
|
DEBUG3 - 10:53:33.353228206 [15415/15423]: Created hashtable size 4 at 0x22bc090 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:33.353235997 [15415/15423]: Created hashtable size 4 at 0x22cbfe0 of type 0 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:33.353242851 [15415/15423]: UST app channel channel0 allocated (in alloc_ust_app_channel() at ust-app.c:1049)
|
|
DEBUG2 - 10:53:33.353249491 [15415/15423]: UST app shadow copy of channel channel0 started (in shadow_copy_channel() at ust-app.c:1792)
|
|
DEBUG3 - 10:53:33.353256563 [15415/15423]: UST app shadow copy of channel channel0 done (in shadow_copy_channel() at ust-app.c:1846)
|
|
DEBUG1 - 10:53:33.353263187 [15415/15423]: UST app creating channel channel0 with per UID buffers (in create_channel_per_uid() at ust-app.c:2864)
|
|
DEBUG3 - 10:53:33.353269800 [15415/15423]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG1 - 10:53:33.353277567 [15415/15423]: UST app sending buffer registry channel to ust sock 41 (in send_channel_uid_to_ust() at ust-app.c:2794)
|
|
DEBUG2 - 10:53:33.353287950 [15415/15423]: UST app send channel to sock 41 pid 15014 (name: channel0, key: 0) (in ust_consumer_send_channel_to_ust() at ust-consumer.c:445)
|
|
DEBUG2 - 10:53:33.354450854 [15415/15423]: UST consumer send stream to app 41 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:408)
|
|
DEBUG2 - 10:53:33.354518082 [15415/15423]: UST app create channel channel0 for PID 15014 completed (in create_ust_app_channel() at ust-app.c:3157)
|
|
DEBUG2 - 10:53:33.354531271 [15415/15423]: Channel channel0 created successfully (in channel_ust_create() at channel.c:490)
|
|
DEBUG2 - 10:53:33.354539601 [15415/15423]: Trace UST channel channel0 found by name (in trace_ust_find_channel_by_name() at trace-ust.c:191)
|
|
DEBUG2 - 10:53:33.354553369 [15415/15423]: Trace UST event hello_world:my_first_tracepoint NOT found (in trace_ust_find_event() at trace-ust.c:234)
|
|
DEBUG2 - 10:53:33.354562395 [15415/15423]: Trace UST event hello_world:my_first_tracepoint, loglevel (0,-1) created (in trace_ust_create_event() at trace-ust.c:512)
|
|
DEBUG1 - 10:53:33.354572994 [15415/15423]: UST app creating event hello_world:my_first_tracepoint for all apps for session id 0 (in ust_app_create_event_glb() at ust-app.c:4328)
|
|
DEBUG3 - 10:53:33.354583245 [15415/15423]: UST app event hello_world:my_first_tracepoint allocated (in alloc_ust_app_event() at ust-app.c:1105)
|
|
DEBUG2 - 10:53:33.354636406 [15415/15423]: UST app event hello_world:my_first_tracepoint created successfully for pid:14173 (in create_ust_event() at ust-app.c:1692)
|
|
DEBUG2 - 10:53:33.354675265 [15415/15423]: UST app event hello_world:my_first_tracepoint enabled successfully for app (pid: 14173) (in enable_ust_event() at ust-app.c:1596)
|
|
DEBUG2 - 10:53:33.354683301 [15415/15423]: UST app create event hello_world:my_first_tracepoint for PID 14173 completed (in create_ust_app_event() at ust-app.c:3216)
|
|
DEBUG3 - 10:53:33.354690263 [15415/15423]: UST app event hello_world:my_first_tracepoint allocated (in alloc_ust_app_event() at ust-app.c:1105)
|
|
DEBUG2 - 10:53:33.354725917 [15415/15423]: UST app event hello_world:my_first_tracepoint created successfully for pid:7495 (in create_ust_event() at ust-app.c:1692)
|
|
DEBUG2 - 10:53:33.354759636 [15415/15423]: UST app event hello_world:my_first_tracepoint enabled successfully for app (pid: 7495) (in enable_ust_event() at ust-app.c:1596)
|
|
DEBUG2 - 10:53:33.354769356 [15415/15423]: UST app create event hello_world:my_first_tracepoint for PID 7495 completed (in create_ust_app_event() at ust-app.c:3216)
|
|
DEBUG3 - 10:53:33.354775686 [15415/15423]: UST app event hello_world:my_first_tracepoint allocated (in alloc_ust_app_event() at ust-app.c:1105)
|
|
DEBUG2 - 10:53:33.354821892 [15415/15423]: UST app event hello_world:my_first_tracepoint created successfully for pid:15014 (in create_ust_event() at ust-app.c:1692)
|
|
DEBUG2 - 10:53:33.354861709 [15415/15423]: UST app event hello_world:my_first_tracepoint enabled successfully for app (pid: 15014) (in enable_ust_event() at ust-app.c:1596)
|
|
DEBUG2 - 10:53:33.354873155 [15415/15423]: UST app create event hello_world:my_first_tracepoint for PID 15014 completed (in create_ust_app_event() at ust-app.c:3216)
|
|
DEBUG1 - 10:53:33.354878497 [15415/15423]: Event UST hello_world:my_first_tracepoint created in channel channel0 (in event_ust_enable_tracepoint() at event.c:236)
|
|
DEBUG1 - 10:53:33.354887823 [15415/15423]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
|
|
DEBUG1 - 10:53:33.354913724 [15415/15423]: Clean command context structure (in clean_command_ctx() at main.c:641)
|
|
DEBUG1 - 10:53:33.354925461 [15415/15423]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
|
|
DEBUG1 - 10:53:34.352276244 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:34.352270212 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:34.352291542 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:34.352304760 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:34.352312971 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:35.352254740 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:35.352260024 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:35.352274580 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:35.352283425 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:35.352288951 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:36.352254915 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:36.352260346 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:36.352272105 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:36.352282287 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:36.352290279 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:37.352256239 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:37.352262573 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:37.352273655 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:37.352282495 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:37.352288030 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:38.352256775 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:38.352261754 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:38.352277022 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:38.352285766 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:38.352291813 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:39.352259733 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:39.352265858 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:39.352278970 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:39.352288793 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:39.352294440 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:40.352256516 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:40.352262209 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:40.352273448 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:40.352282117 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:40.352287756 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:41.352259298 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:41.352264569 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:41.352277860 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:41.352291661 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:41.352297570 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:42.352256894 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:42.352263564 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:42.352278185 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:42.352286761 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:42.352292380 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:43.212330176 [15415/15423]: Wait for client response (in thread_manage_clients() at main.c:4389)
|
|
DEBUG1 - 10:53:43.212402463 [15415/15423]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
|
|
DEBUG1 - 10:53:43.212427542 [15415/15423]: Processing client command 0 (in process_client_msg() at main.c:2877)
|
|
DEBUG1 - 10:53:43.212447146 [15415/15423]: Getting session auto-20200115-105324 by name (in process_client_msg() at main.c:2970)
|
|
DEBUG2 - 10:53:43.212454924 [15415/15423]: Trying to find session by name auto-20200115-105324 (in session_find_by_name() at session.c:276)
|
|
DEBUG3 - 10:53:43.212467057 [15415/15423]: Consumer socket created (fd: 45) and added to output (in consumer_create_socket() at consumer.c:301)
|
|
DEBUG1 - 10:53:43.212478031 [15415/15423]: Setting relayd for session auto-20200115-105324 (in cmd_setup_relayd() at cmd.c:1043)
|
|
DEBUG2 - 10:53:43.212508053 [15415/15423]: UST app adding context to channel channel0 (in create_ust_app_channel_context() at ust-app.c:2357)
|
|
DEBUG3 - 10:53:43.212522490 [15415/15423]: UST app context 1 allocated (in alloc_ust_app_ctx() at ust-app.c:1146)
|
|
DEBUG2 - 10:53:43.212583036 [15415/15423]: UST app context handle -1 created successfully for channel channel0 (in create_ust_channel_context() at ust-app.c:1321)
|
|
DEBUG2 - 10:53:43.212596070 [15415/15423]: UST app adding context to channel channel0 (in create_ust_app_channel_context() at ust-app.c:2357)
|
|
DEBUG3 - 10:53:43.212604805 [15415/15423]: UST app context 1 allocated (in alloc_ust_app_ctx() at ust-app.c:1146)
|
|
DEBUG2 - 10:53:43.212652711 [15415/15423]: UST app context handle -1 created successfully for channel channel0 (in create_ust_channel_context() at ust-app.c:1321)
|
|
DEBUG2 - 10:53:43.212665258 [15415/15423]: UST app adding context to channel channel0 (in create_ust_app_channel_context() at ust-app.c:2357)
|
|
DEBUG3 - 10:53:43.212673850 [15415/15423]: UST app context 1 allocated (in alloc_ust_app_ctx() at ust-app.c:1146)
|
|
DEBUG2 - 10:53:43.212753152 [15415/15423]: UST app context handle -1 created successfully for channel channel0 (in create_ust_channel_context() at ust-app.c:1321)
|
|
DEBUG1 - 10:53:43.212765659 [15415/15423]: Context UST 1 added to channel channel0 (in add_uctx_to_channel() at context.c:184)
|
|
DEBUG1 - 10:53:43.212775715 [15415/15423]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
|
|
DEBUG1 - 10:53:43.212799413 [15415/15423]: Clean command context structure (in clean_command_ctx() at main.c:641)
|
|
DEBUG1 - 10:53:43.212811290 [15415/15423]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
|
|
DEBUG1 - 10:53:43.212890485 [15415/15423]: Wait for client response (in thread_manage_clients() at main.c:4389)
|
|
DEBUG1 - 10:53:43.212912934 [15415/15423]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
|
|
DEBUG1 - 10:53:43.212933815 [15415/15423]: Processing client command 0 (in process_client_msg() at main.c:2877)
|
|
DEBUG1 - 10:53:43.212944056 [15415/15423]: Getting session auto-20200115-105324 by name (in process_client_msg() at main.c:2970)
|
|
DEBUG2 - 10:53:43.212951252 [15415/15423]: Trying to find session by name auto-20200115-105324 (in session_find_by_name() at session.c:276)
|
|
DEBUG3 - 10:53:43.212959574 [15415/15423]: Consumer socket created (fd: 45) and added to output (in consumer_create_socket() at consumer.c:301)
|
|
DEBUG1 - 10:53:43.212966793 [15415/15423]: Setting relayd for session auto-20200115-105324 (in cmd_setup_relayd() at cmd.c:1043)
|
|
DEBUG2 - 10:53:43.212976837 [15415/15423]: UST app adding context to channel channel0 (in create_ust_app_channel_context() at ust-app.c:2357)
|
|
DEBUG3 - 10:53:43.212984243 [15415/15423]: UST app context 2 allocated (in alloc_ust_app_ctx() at ust-app.c:1146)
|
|
DEBUG2 - 10:53:43.213026850 [15415/15423]: UST app context handle -1 created successfully for channel channel0 (in create_ust_channel_context() at ust-app.c:1321)
|
|
DEBUG2 - 10:53:43.213037808 [15415/15423]: UST app adding context to channel channel0 (in create_ust_app_channel_context() at ust-app.c:2357)
|
|
DEBUG3 - 10:53:43.213045070 [15415/15423]: UST app context 2 allocated (in alloc_ust_app_ctx() at ust-app.c:1146)
|
|
DEBUG2 - 10:53:43.213084246 [15415/15423]: UST app context handle -1 created successfully for channel channel0 (in create_ust_channel_context() at ust-app.c:1321)
|
|
DEBUG2 - 10:53:43.213095119 [15415/15423]: UST app adding context to channel channel0 (in create_ust_app_channel_context() at ust-app.c:2357)
|
|
DEBUG3 - 10:53:43.213102392 [15415/15423]: UST app context 2 allocated (in alloc_ust_app_ctx() at ust-app.c:1146)
|
|
DEBUG2 - 10:53:43.213147259 [15415/15423]: UST app context handle -1 created successfully for channel channel0 (in create_ust_channel_context() at ust-app.c:1321)
|
|
DEBUG1 - 10:53:43.213158049 [15415/15423]: Context UST 2 added to channel channel0 (in add_uctx_to_channel() at context.c:184)
|
|
DEBUG1 - 10:53:43.213165411 [15415/15423]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
|
|
DEBUG1 - 10:53:43.213183511 [15415/15423]: Clean command context structure (in clean_command_ctx() at main.c:641)
|
|
DEBUG1 - 10:53:43.213193515 [15415/15423]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
|
|
DEBUG1 - 10:53:43.352259409 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:43.352265169 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:43.352279184 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:43.352287892 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:43.352293823 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:44.352257856 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:44.352262864 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:44.352278293 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:44.352286990 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:44.352292281 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:45.352255868 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:45.352261364 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:45.352273063 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:45.352281598 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:45.352291281 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:46.352255422 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:46.352260893 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:46.352272815 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:46.352283486 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:46.352290139 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:47.352255754 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:47.352261485 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:47.352273341 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:47.352282324 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:47.352290307 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:48.352254513 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:48.352259704 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:48.352272585 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:48.352283744 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:48.352289689 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:49.352258781 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:49.352264051 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:49.352277593 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:49.352285928 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:49.352291674 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:50.193577788 [15415/15423]: Wait for client response (in thread_manage_clients() at main.c:4389)
|
|
DEBUG1 - 10:53:50.193605659 [15415/15423]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
|
|
DEBUG1 - 10:53:50.193616834 [15415/15423]: Processing client command 16 (in process_client_msg() at main.c:2877)
|
|
DEBUG1 - 10:53:50.193622115 [15415/15423]: Getting session auto-20200115-105324 by name (in process_client_msg() at main.c:2970)
|
|
DEBUG2 - 10:53:50.193626885 [15415/15423]: Trying to find session by name auto-20200115-105324 (in session_find_by_name() at session.c:276)
|
|
DEBUG1 - 10:53:50.193633107 [15415/15423]: Starting all UST traces (in ust_app_start_trace_all() at ust-app.c:4929)
|
|
DEBUG1 - 10:53:50.193636842 [15415/15423]: Clearing stream quiescent state for all ust apps (in ust_app_clear_quiescent_session() at ust-app.c:4804)
|
|
DEBUG2 - 10:53:50.193646219 [15415/15423]: Consumer clear quiescent channel key 1 (in consumer_clear_quiescent_channel() at consumer.c:1252)
|
|
DEBUG1 - 10:53:50.193670538 [16083/16092]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
|
|
DEBUG1 - 10:53:50.193693968 [16083/16092]: UST consumer clear quiescent channel key 1 (in clear_quiescent_channel() at ust-consumer.c:796)
|
|
DEBUG1 - 10:53:50.193709034 [16083/16092]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
|
|
DEBUG1 - 10:53:50.193726107 [15415/15423]: Starting tracing for ust app pid 14173 (in ust_app_start_trace() at ust-app.c:4392)
|
|
DEBUG3 - 10:53:50.193737024 [15415/15423]: mkdir() recursive /var/lib/log/lttng_home/lttng-traces/auto-20200115-105324 with mode 504 for uid 1000 and gid 1000 (in run_as_mkdir_recursive() at runas.c:470)
|
|
DEBUG1 - 10:53:50.193747953 [15415/15423]: Using run_as worker (in run_as() at runas.c:450)
|
|
DEBUG3 - 10:53:50.193802070 [15415/15423]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG3 - 10:53:50.193829469 [15415/15423]: Created hashtable size 4 at 0x22c8380 of type 1 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:50.193835338 [15415/15423]: Created hashtable size 4 at 0x22c8710 of type 0 (in lttng_ht_new() at hashtable.c:145)
|
|
DEBUG3 - 10:53:50.193839116 [15415/15423]: UST app channel metadata allocated (in alloc_ust_app_channel() at ust-app.c:1049)
|
|
DEBUG3 - 10:53:50.193846030 [15415/15423]: Session 0 found by id. (in session_find_by_id() at session.c:312)
|
|
DEBUG2 - 10:53:50.193851282 [15415/15423]: Asking UST consumer for channel (in ask_channel_creation() at ust-consumer.c:121)
|
|
DEBUG3 - 10:53:50.193860526 [15415/15423]: mkdir() recursive /var/lib/log/lttng_home/lttng-traces/auto-20200115-105324/ust/uid/1000/64-bit with mode 504 for uid 1000 and gid 1000 (in run_as_mkdir_recursive() at runas.c:470)
|
|
DEBUG1 - 10:53:50.193873034 [15415/15423]: Using run_as worker (in run_as() at runas.c:450)
|
|
DEBUG1 - 10:53:50.193938543 [16083/16092]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
|
|
DEBUG1 - 10:53:50.193971603 [16083/16092]: Allocated channel (key 4) (in consumer_allocate_channel() at consumer.c:1031)
|
|
DEBUG1 - 10:53:50.194087064 [16083/16092]: Using run_as worker (in run_as() at runas.c:450)
|
|
DEBUG1 - 10:53:50.194174725 [16083/16092]: UST consumer add stream metadata (key: 43) with relayd id 0 (in create_ust_streams() at ust-consumer.c:347)
|
|
DEBUG1 - 10:53:50.194184894 [16083/16092]: Allocated metadata cache of 4096 bytes (in consumer_metadata_cache_allocate() at consumer-metadata-cache.c:198)
|
|
DEBUG1 - 10:53:50.194194103 [16083/16092]: UST consumer channel added (key: 4) (in add_channel() at ust-consumer.c:115)
|
|
DEBUG1 - 10:53:50.194203113 [16083/16092]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
|
|
DEBUG2 - 10:53:50.194209723 [15415/15423]: UST ask channel 4 successfully done with 1 stream(s) (in ask_channel_creation() at ust-consumer.c:218)
|
|
DEBUG2 - 10:53:50.194217981 [15415/15423]: Consumer setup metadata channel key 4 (in consumer_setup_metadata() at consumer.c:1319)
|
|
DEBUG1 - 10:53:50.194236389 [16083/16092]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
|
|
DEBUG1 - 10:53:50.194248879 [16083/16092]: UST consumer setup metadata key 4 (in setup_metadata() at ust-consumer.c:912)
|
|
DEBUG1 - 10:53:50.194266496 [16083/16092]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
|
|
DEBUG2 - 10:53:50.194268669 [15415/15423]: UST metadata with key 4 created for app pid 14173 (in create_ust_app_metadata() at ust-app.c:3316)
|
|
DEBUG1 - 10:53:50.194267036 [16083/16090]: Metadata poll return from wait with 1 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2284)
|
|
DEBUG3 - 10:53:50.194273371 [15415/15423]: UST app deleting channel metadata (in delete_ust_app_channel() at ust-app.c:460)
|
|
DEBUG1 - 10:53:50.194276858 [16083/16090]: Metadata event caught in thread (in consumer_thread_metadata_poll() at consumer.c:2286)
|
|
DEBUG1 - 10:53:50.194282856 [16083/16090]: Adding metadata stream 43 to poll set (in consumer_thread_metadata_poll() at consumer.c:2340)
|
|
DEBUG1 - 10:53:50.194289374 [16083/16090]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2281)
|
|
DEBUG3 - 10:53:50.194335163 [15415/15427]: [ust-thread] Manage notify return from poll on 5 fds (in ust_thread_manage_notify() at ust-thread.c:76)
|
|
DEBUG3 - 10:53:50.194385274 [15415/15427]: UST app receiving notify from sock 39 (in ust_app_recv_notify() at ust-app.c:5699)
|
|
DEBUG2 - 10:53:50.194426657 [15415/15427]: UST app ustctl register channel received (in ust_app_recv_notify() at ust-app.c:5753)
|
|
DEBUG3 - 10:53:50.194462029 [15415/15427]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG3 - 10:53:50.194484631 [15415/15427]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:796)
|
|
DEBUG3 - 10:53:50.194501164 [15415/15427]: Append to metadata: "stream {
|
|
id = 0;
|
|
event.header := struct event_header_compact;
|
|
packet.context := struct packet_context;
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.194510887 [15415/15427]: Append to metadata: " event.context := struct {
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.194519873 [15415/15427]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.194527871 [15415/15427]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.194538289 [15415/15427]: Append to metadata: "integer { size = 32; align = 8; signed = 1; encoding = none; base = 10; } _vpid;
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.194545942 [15415/15427]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.194553051 [15415/15427]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.194562266 [15415/15427]: Append to metadata: "integer { size = 64; align = 8; signed = 0; encoding = none; base = 10; } _pthread_id;
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.194569777 [15415/15427]: Append to metadata: " };
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.194576936 [15415/15427]: Append to metadata: "};
|
|
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.194583554 [15415/15427]: UST app replying to register channel key 0 with id 0, type: 1, ret: 0 (in reply_ust_register_channel() at ust-app.c:5479)
|
|
DEBUG3 - 10:53:50.194607232 [15415/15427]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
|
|
DEBUG1 - 10:53:50.204226238 [15415/15423]: Starting tracing for ust app pid 7495 (in ust_app_start_trace() at ust-app.c:4392)
|
|
DEBUG3 - 10:53:50.204236347 [15415/15423]: mkdir() recursive /var/lib/log/lttng_home/lttng-traces/auto-20200115-105324 with mode 504 for uid 1000 and gid 1000 (in run_as_mkdir_recursive() at runas.c:470)
|
|
DEBUG1 - 10:53:50.204246410 [15415/15423]: Using run_as worker (in run_as() at runas.c:450)
|
|
DEBUG3 - 10:53:50.204289002 [15415/15423]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG3 - 10:53:50.204331673 [15415/15427]: [ust-thread] Manage notify return from poll on 5 fds (in ust_thread_manage_notify() at ust-thread.c:76)
|
|
DEBUG3 - 10:53:50.204364669 [15415/15427]: UST app receiving notify from sock 37 (in ust_app_recv_notify() at ust-app.c:5699)
|
|
DEBUG2 - 10:53:50.204377555 [15415/15427]: UST app ustctl register channel received (in ust_app_recv_notify() at ust-app.c:5753)
|
|
DEBUG3 - 10:53:50.204403790 [15415/15427]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG3 - 10:53:50.204416293 [15415/15427]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:796)
|
|
DEBUG3 - 10:53:50.204423831 [15415/15427]: UST app replying to register channel key 0 with id 0, type: 1, ret: 0 (in reply_ust_register_channel() at ust-app.c:5479)
|
|
DEBUG3 - 10:53:50.204453420 [15415/15427]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
|
|
DEBUG1 - 10:53:50.213666854 [15415/15423]: Starting tracing for ust app pid 15014 (in ust_app_start_trace() at ust-app.c:4392)
|
|
DEBUG3 - 10:53:50.213680673 [15415/15423]: mkdir() recursive /var/lib/log/lttng_home/lttng-traces/auto-20200115-105324 with mode 504 for uid 1000 and gid 1000 (in run_as_mkdir_recursive() at runas.c:470)
|
|
DEBUG1 - 10:53:50.213692886 [15415/15423]: Using run_as worker (in run_as() at runas.c:450)
|
|
DEBUG3 - 10:53:50.213737064 [15415/15423]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG3 - 10:53:50.213806673 [15415/15427]: [ust-thread] Manage notify return from poll on 5 fds (in ust_thread_manage_notify() at ust-thread.c:76)
|
|
DEBUG3 - 10:53:50.213822855 [15415/15427]: UST app receiving notify from sock 42 (in ust_app_recv_notify() at ust-app.c:5699)
|
|
DEBUG2 - 10:53:50.213834326 [15415/15427]: UST app ustctl register channel received (in ust_app_recv_notify() at ust-app.c:5753)
|
|
DEBUG3 - 10:53:50.213857980 [15415/15427]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG3 - 10:53:50.213869907 [15415/15427]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:796)
|
|
DEBUG3 - 10:53:50.213877350 [15415/15427]: UST app replying to register channel key 0 with id 0, type: 1, ret: 0 (in reply_ust_register_channel() at ust-app.c:5479)
|
|
DEBUG3 - 10:53:50.213900036 [15415/15427]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
|
|
DEBUG3 - 10:53:50.213913338 [15415/15427]: [ust-thread] Manage notify return from poll on 5 fds (in ust_thread_manage_notify() at ust-thread.c:76)
|
|
DEBUG3 - 10:53:50.213920346 [15415/15427]: UST app receiving notify from sock 42 (in ust_app_recv_notify() at ust-app.c:5699)
|
|
DEBUG2 - 10:53:50.213929449 [15415/15427]: UST app ustctl register event received (in ust_app_recv_notify() at ust-app.c:5719)
|
|
DEBUG3 - 10:53:50.213960316 [15415/15427]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG3 - 10:53:50.213971923 [15415/15427]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:796)
|
|
DEBUG3 - 10:53:50.213980264 [15415/15427]: UST registry creating event with event: hello_world:my_first_tracepoint, sig: int, my_integer_arg, char*, my_string_arg, id: 0, chan_objd: 2, sess_objd: 1, chan_id: 0 (in ust_registry_create_event() at ust-registry.c:426)
|
|
DEBUG3 - 10:53:50.214001330 [15415/15427]: Append to metadata: "event {
|
|
name = "hello_world:my_first_tracepoint";
|
|
id = 0;
|
|
stream_id = 0;
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.214013852 [15415/15427]: Append to metadata: " loglevel = 13;
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.214021967 [15415/15427]: Append to metadata: " fields := struct {
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.214030236 [15415/15427]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.214037942 [15415/15427]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.214045623 [15415/15427]: Append to metadata: "string _my_string_field;
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.214053147 [15415/15427]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.214060258 [15415/15427]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.214070392 [15415/15427]: Append to metadata: "integer { size = 32; align = 8; signed = 1; encoding = none; base = 10; } _my_integer_field;
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.214077802 [15415/15427]: Append to metadata: " };
|
|
};
|
|
|
|
" (in lttng_metadata_printf() at ust-metadata.c:178)
|
|
DEBUG3 - 10:53:50.214093374 [15415/15427]: UST registry event hello_world:my_first_tracepoint with id 0 added successfully (in add_event_ust_registry() at ust-app.c:5593)
|
|
DEBUG3 - 10:53:50.214101983 [15415/15427]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
|
|
DEBUG1 - 10:53:50.267980421 [15415/15423]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
|
|
DEBUG1 - 10:53:50.268003868 [15415/15423]: Clean command context structure (in clean_command_ctx() at main.c:641)
|
|
DEBUG1 - 10:53:50.268009215 [15415/15423]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
|
|
DEBUG3 - 10:53:50.269034240 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:53:50.279131416 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:53:50.279143932 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:53:50.289222758 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG1 - 10:53:50.352256489 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:50.352261180 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:50.352271198 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:50.352279353 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:50.352284819 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:51.352255258 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:51.352261726 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:51.352272439 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:51.352281662 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:51.352287424 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:52.352258364 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:52.352263379 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:52.352275344 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:52.352284628 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:52.352290353 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:53.352258638 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:53.352264053 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:53.352278286 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:53.352287827 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:53.352293814 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:54.352256775 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:54.352261477 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:54.352274385 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:54.352285993 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:54.352291877 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:55.352255693 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:55.352261176 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:55.352272494 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:55.352285019 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:55.352291014 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:56.352255728 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:56.352261644 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:56.352274382 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:56.352284274 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:56.352290107 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:57.352254398 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:57.352259621 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:57.352272286 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:57.352281396 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:57.352286894 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:58.352256646 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:58.352264335 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:58.352275969 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:58.352287275 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:58.352293703 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:53:59.352255291 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:53:59.352263029 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:53:59.352275011 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:53:59.352283862 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:53:59.352289375 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:00.352259021 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:54:00.352263939 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:00.352280705 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:00.352290018 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:54:00.352295979 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:01.352260930 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:01.352254956 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:54:01.352276316 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:01.352284981 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:54:01.352290593 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:01.421613358 [15415/15426]: Apps thread return from poll on 5 fds (in thread_manage_apps() at main.c:1480)
|
|
DEBUG3 - 10:54:01.421613798 [15415/15427]: [ust-thread] Manage notify return from poll on 5 fds (in ust_thread_manage_notify() at ust-thread.c:76)
|
|
DEBUG1 - 10:54:01.421645104 [15415/15426]: PID 15014 unregistering with sock 41 (in ust_app_unregister() at ust-app.c:3508)
|
|
DEBUG3 - 10:54:01.421648192 [15415/15427]: UST app receiving notify from sock 42 (in ust_app_recv_notify() at ust-app.c:5699)
|
|
DEBUG3 - 10:54:01.421655496 [15415/15426]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG3 - 10:54:01.421657277 [15415/15427]: UST app recv notify failed. Application died (in ust_app_recv_notify() at ust-app.c:5706)
|
|
DEBUG1 - 10:54:01.421678330 [15415/15427]: UST app notify socket unregister 42 (in ust_app_notify_sock_unregister() at ust-app.c:5856)
|
|
DEBUG2 - 10:54:01.421678486 [15415/15426]: Consumer push metadata to consumer socket 45 (in consumer_push_metadata() at consumer.c:1354)
|
|
DEBUG3 - 10:54:01.421693142 [15415/15427]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
|
|
DEBUG1 - 10:54:01.421737673 [16083/16092]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
|
|
DEBUG1 - 10:54:01.421757029 [16083/16092]: UST consumer push metadata key 4 of len 2823 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1681)
|
|
DEBUG3 - 10:54:01.421774993 [15415/15426]: Consumer pushing metadata on sock 45 of len 2823 (in consumer_push_metadata() at consumer.c:1372)
|
|
DEBUG1 - 10:54:01.421799028 [16083/16092]: UST consumer push metadata key 4 of len 2823 (in lttng_ustconsumer_recv_metadata() at ust-consumer.c:1267)
|
|
DEBUG1 - 10:54:01.421821868 [16083/16092]: Writing 2823 bytes from offset 0 in metadata cache (in consumer_metadata_cache_write() at consumer-metadata-cache.c:134)
|
|
DEBUG1 - 10:54:01.421833760 [16083/16092]: Waiting for metadata to be flushed (in lttng_ustconsumer_recv_metadata() at ust-consumer.c:1308)
|
|
DEBUG1 - 10:54:01.421838158 [16083/16090]: Metadata poll return from wait with 2 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2284)
|
|
DEBUG1 - 10:54:01.421846247 [16083/16090]: Metadata event caught in thread (in consumer_thread_metadata_poll() at consumer.c:2286)
|
|
DEBUG1 - 10:54:01.421851727 [16083/16090]: Metadata available on fd 43 (in consumer_thread_metadata_poll() at consumer.c:2378)
|
|
DEBUG1 - 10:54:01.421862663 [16083/16090]: In UST read_subbuffer (wait_fd: 43, name: metadata) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
|
|
DEBUG1 - 10:54:01.421932873 [16083/16090]: Consumer mmap write() ret 4096 (len 4096) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1670)
|
|
DEBUG1 - 10:54:01.421998183 [16083/16090]: In UST read_subbuffer (wait_fd: 43, name: metadata) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
|
|
DEBUG1 - 10:54:01.422007297 [16083/16090]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2281)
|
|
DEBUG1 - 10:54:01.621909049 [16083/16092]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
|
|
DEBUG1 - 10:54:01.621930893 [15415/15426]: Apps thread polling (in thread_manage_apps() at main.c:1473)
|
|
DEBUG3 - 10:54:01.632007931 [15415/16093]: Call RCU deleting app PID 15014 (in delete_ust_app_rcu() at ust-app.c:944)
|
|
DEBUG3 - 10:54:01.632031139 [15415/16093]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG3 - 10:54:01.632045253 [15415/16093]: No metadata to push for metadata key 4 (in ust_app_push_metadata() at ust-app.c:579)
|
|
DEBUG3 - 10:54:01.632053301 [15415/16093]: UST app deleting channel channel0 (in delete_ust_app_channel() at ust-app.c:460)
|
|
DEBUG3 - 10:54:01.632094953 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG2 - 10:54:01.632102454 [15415/16093]: UST app pid 15014 deleted (in delete_ust_app() at ust-app.c:928)
|
|
DEBUG3 - 10:54:01.642197696 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:01.642212210 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:01.667561202 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:01.667588359 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:01.677688169 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:01.677707943 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:01.687802749 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:01.687815340 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:01.697902463 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:01.697914606 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:01.707998867 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG1 - 10:54:02.352268664 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:02.352263499 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:54:02.352289640 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:02.352298866 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:54:02.352305114 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:03.352254181 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:54:03.352259157 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:03.352271375 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:03.352280122 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:54:03.352285761 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:04.352257153 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:54:04.352261865 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:04.352274903 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:04.352285964 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:54:04.352291669 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:05.352259356 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:54:05.352264505 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:05.352277265 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:05.352288619 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:54:05.352294786 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:06.352257476 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:54:06.352263028 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:06.352274586 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:06.352283913 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:54:06.352291584 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:07.352259933 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:54:07.352281351 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:07.352292749 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:07.352301906 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:54:07.352307728 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:08.352259695 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:54:08.352264787 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:08.352278937 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:08.352288014 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:54:08.352293568 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:09.352257642 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:54:09.352262904 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:09.352275275 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:09.352284237 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:54:09.352289819 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:10.352259951 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:54:10.352266923 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:10.352278685 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:10.352287063 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:54:10.352292745 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:11.352256826 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:54:11.352268310 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:11.352280505 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:11.352289598 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:54:11.352295298 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:12.352259277 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:54:12.352264681 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:12.352278180 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:12.352287086 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:54:12.352292984 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:13.352260308 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:54:13.352265802 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:13.352280049 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:13.352288945 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:54:13.352294608 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:14.352260494 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:54:14.352265260 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:14.352276990 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:14.352286125 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:54:14.352291947 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:15.352257042 [16083/16088]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
|
|
DEBUG1 - 10:54:15.352262830 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:15.352277171 [15415/15422]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:15.352285638 [15415/15422]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200115-105324 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
|
|
DEBUG1 - 10:54:15.352291388 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:16.047497510 [15415/15423]: Wait for client response (in thread_manage_clients() at main.c:4389)
|
|
DEBUG1 - 10:54:16.047532832 [15415/15423]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
|
|
DEBUG1 - 10:54:16.047545972 [15415/15423]: Processing client command 13 (in process_client_msg() at main.c:2877)
|
|
DEBUG1 - 10:54:16.047552154 [15415/15423]: Counting number of available session for UID 1000 GID 1000 (in lttng_sessions_count() at main.c:2846)
|
|
DEBUG1 - 10:54:16.047561600 [15415/15423]: Getting all available session for UID 1000 GID 1000 (in cmd_list_lttng_sessions() at cmd.c:3092)
|
|
DEBUG1 - 10:54:16.047573328 [15415/15423]: Sending response (size: 4396, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
|
|
DEBUG1 - 10:54:16.047589029 [15415/15423]: Clean command context structure (in clean_command_ctx() at main.c:641)
|
|
DEBUG1 - 10:54:16.047595300 [15415/15423]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
|
|
DEBUG1 - 10:54:16.047728123 [15415/15423]: Wait for client response (in thread_manage_clients() at main.c:4389)
|
|
DEBUG1 - 10:54:16.047749509 [15415/15423]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
|
|
DEBUG1 - 10:54:16.047761770 [15415/15423]: Processing client command 17 (in process_client_msg() at main.c:2877)
|
|
DEBUG1 - 10:54:16.047768143 [15415/15423]: Getting session auto-20200115-105324 by name (in process_client_msg() at main.c:2970)
|
|
DEBUG2 - 10:54:16.047773517 [15415/15423]: Trying to find session by name auto-20200115-105324 (in session_find_by_name() at session.c:276)
|
|
DEBUG1 - 10:54:16.047779162 [15415/15423]: Stopping all UST traces (in ust_app_stop_trace_all() at ust-app.c:4964)
|
|
DEBUG1 - 10:54:16.047783577 [15415/15423]: Stopping tracing for ust app pid 14173 (in ust_app_stop_trace() at ust-app.c:4502)
|
|
DEBUG3 - 10:54:16.047884381 [15415/15423]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG3 - 10:54:16.047894606 [15415/15423]: No metadata to push for metadata key 4 (in ust_app_push_metadata() at ust-app.c:579)
|
|
DEBUG1 - 10:54:16.047898891 [15415/15423]: Stopping tracing for ust app pid 7495 (in ust_app_stop_trace() at ust-app.c:4502)
|
|
DEBUG3 - 10:54:16.048029571 [15415/15423]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG3 - 10:54:16.048036287 [15415/15423]: No metadata to push for metadata key 4 (in ust_app_push_metadata() at ust-app.c:579)
|
|
DEBUG1 - 10:54:16.048039710 [15415/15423]: Flushing session buffers for all ust apps (in ust_app_flush_session() at ust-app.c:4659)
|
|
DEBUG2 - 10:54:16.048044309 [15415/15423]: Consumer flush channel key 1 (in consumer_flush_channel() at consumer.c:1220)
|
|
DEBUG1 - 10:54:16.048072353 [16083/16092]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
|
|
DEBUG1 - 10:54:16.048100572 [16083/16092]: UST consumer flush channel key 1 (in flush_channel() at ust-consumer.c:751)
|
|
DEBUG1 - 10:54:16.048131143 [16083/16091]: poll num_rdy : 1 (in consumer_thread_data_poll() at consumer.c:2551)
|
|
DEBUG3 - 10:54:16.048135913 [15415/15423]: No metadata to push for metadata key 4 (in ust_app_push_metadata() at ust-app.c:579)
|
|
DEBUG1 - 10:54:16.048143167 [15415/15423]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
|
|
DEBUG1 - 10:54:16.048147017 [16083/16091]: Normal read on fd 35 (in consumer_thread_data_poll() at consumer.c:2658)
|
|
DEBUG1 - 10:54:16.048155277 [15415/15423]: Clean command context structure (in clean_command_ctx() at main.c:641)
|
|
DEBUG1 - 10:54:16.048133620 [16083/16092]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
|
|
DEBUG1 - 10:54:16.048155031 [16083/16091]: In UST read_subbuffer (wait_fd: 35, name: channel0_0) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
|
|
DEBUG1 - 10:54:16.048161237 [15415/15423]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
|
|
DEBUG1 - 10:54:16.048202108 [16083/16091]: Consumer mmap write() ret 4096 (len 4096) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1670)
|
|
DEBUG1 - 10:54:16.048259217 [16083/16091]: polling on 3 fd (in consumer_thread_data_poll() at consumer.c:2544)
|
|
DEBUG1 - 10:54:16.048270689 [15415/15423]: Wait for client response (in thread_manage_clients() at main.c:4389)
|
|
DEBUG1 - 10:54:16.048287680 [15415/15423]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
|
|
DEBUG1 - 10:54:16.048297091 [15415/15423]: Processing client command 24 (in process_client_msg() at main.c:2877)
|
|
DEBUG1 - 10:54:16.048300619 [15415/15423]: Getting session auto-20200115-105324 by name (in process_client_msg() at main.c:2970)
|
|
DEBUG2 - 10:54:16.048303899 [15415/15423]: Trying to find session by name auto-20200115-105324 (in session_find_by_name() at session.c:276)
|
|
DEBUG3 - 10:54:16.048308794 [15415/15423]: Consumer data pending for id 0 (in consumer_is_data_pending() at consumer.c:1164)
|
|
DEBUG1 - 10:54:16.048325138 [16083/16092]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
|
|
DEBUG1 - 10:54:16.048358018 [16083/16092]: UST consumer data pending command for id 0 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1411)
|
|
DEBUG1 - 10:54:16.048364916 [16083/16092]: Consumer data pending command on session id 0 (in consumer_data_pending() at consumer.c:3621)
|
|
DEBUG1 - 10:54:16.048376220 [16083/16092]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2742)
|
|
DEBUG1 - 10:54:16.048382783 [16083/16092]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2742)
|
|
DEBUG1 - 10:54:16.048387291 [16083/16092]: UST consumer metadata pending check: contiguous 2823 vs pushed 2823 (in lttng_ustconsumer_data_pending() at ust-consumer.c:2767)
|
|
DEBUG1 - 10:54:16.048397789 [16083/16092]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
|
|
DEBUG1 - 10:54:16.048400967 [15415/15423]: Consumer data is NOT pending for session id 0 (in consumer_is_data_pending() at consumer.c:1200)
|
|
DEBUG1 - 10:54:16.048409057 [15415/15423]: Sending response (size: 21, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
|
|
DEBUG1 - 10:54:16.048421704 [15415/15423]: Clean command context structure (in clean_command_ctx() at main.c:641)
|
|
DEBUG1 - 10:54:16.048425747 [15415/15423]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
|
|
DEBUG1 - 10:54:16.048479379 [15415/15423]: Wait for client response (in thread_manage_clients() at main.c:4389)
|
|
DEBUG1 - 10:54:16.048490498 [15415/15423]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
|
|
DEBUG1 - 10:54:16.048499161 [15415/15423]: Processing client command 13 (in process_client_msg() at main.c:2877)
|
|
DEBUG1 - 10:54:16.048502802 [15415/15423]: Counting number of available session for UID 1000 GID 1000 (in lttng_sessions_count() at main.c:2846)
|
|
DEBUG1 - 10:54:16.048506978 [15415/15423]: Getting all available session for UID 1000 GID 1000 (in cmd_list_lttng_sessions() at cmd.c:3092)
|
|
DEBUG1 - 10:54:16.048512751 [15415/15423]: Sending response (size: 4396, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
|
|
DEBUG1 - 10:54:16.048525315 [15415/15423]: Clean command context structure (in clean_command_ctx() at main.c:641)
|
|
DEBUG1 - 10:54:16.048530606 [15415/15423]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
|
|
DEBUG1 - 10:54:16.048578818 [15415/15423]: Wait for client response (in thread_manage_clients() at main.c:4389)
|
|
DEBUG1 - 10:54:16.048592671 [15415/15423]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
|
|
DEBUG1 - 10:54:16.048603719 [15415/15423]: Processing client command 11 (in process_client_msg() at main.c:2877)
|
|
DEBUG1 - 10:54:16.048607282 [15415/15423]: Getting session auto-20200115-105324 by name (in process_client_msg() at main.c:2970)
|
|
DEBUG2 - 10:54:16.048610892 [15415/15423]: Trying to find session by name auto-20200115-105324 (in session_find_by_name() at session.c:276)
|
|
DEBUG3 - 10:54:16.048617360 [15415/15423]: Listing domains found UST global domain (in cmd_list_domains() at cmd.c:2894)
|
|
DEBUG1 - 10:54:16.048622686 [15415/15423]: Sending response (size: 328, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
|
|
DEBUG1 - 10:54:16.048632395 [15415/15423]: Clean command context structure (in clean_command_ctx() at main.c:641)
|
|
DEBUG1 - 10:54:16.048637688 [15415/15423]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
|
|
DEBUG1 - 10:54:16.048682435 [15415/15423]: Wait for client response (in thread_manage_clients() at main.c:4389)
|
|
DEBUG1 - 10:54:16.048694933 [15415/15423]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
|
|
DEBUG1 - 10:54:16.048705407 [15415/15423]: Processing client command 10 (in process_client_msg() at main.c:2877)
|
|
DEBUG1 - 10:54:16.048708953 [15415/15423]: Getting session auto-20200115-105324 by name (in process_client_msg() at main.c:2970)
|
|
DEBUG2 - 10:54:16.048712116 [15415/15423]: Trying to find session by name auto-20200115-105324 (in session_find_by_name() at session.c:276)
|
|
DEBUG3 - 10:54:16.048716098 [15415/15423]: Consumer socket created (fd: 45) and added to output (in consumer_create_socket() at consumer.c:301)
|
|
DEBUG1 - 10:54:16.048720033 [15415/15423]: Setting relayd for session auto-20200115-105324 (in cmd_setup_relayd() at cmd.c:1043)
|
|
DEBUG3 - 10:54:16.048724447 [15415/15423]: Number of UST global channels 1 (in cmd_list_channels() at cmd.c:2977)
|
|
DEBUG1 - 10:54:16.048728389 [15415/15423]: Listing channels for session auto-20200115-105324 (in list_lttng_channels() at cmd.c:255)
|
|
DEBUG3 - 10:54:16.048732950 [15415/15423]: Consumer discarded events id 0 (in consumer_get_discarded_events() at consumer.c:1476)
|
|
DEBUG1 - 10:54:16.048748054 [16083/16092]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
|
|
DEBUG1 - 10:54:16.048765943 [16083/16092]: UST consumer discarded events command for session id 0 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1790)
|
|
DEBUG1 - 10:54:16.048772326 [16083/16092]: UST consumer discarded events command for session id 0, channel key 1 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1817)
|
|
DEBUG1 - 10:54:16.048782570 [16083/16092]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
|
|
DEBUG1 - 10:54:16.048784988 [15415/15423]: Consumer discarded 0 events in session id 0 (in consumer_get_discarded_events() at consumer.c:1513)
|
|
DEBUG1 - 10:54:16.048791305 [15415/15423]: Sending response (size: 676, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
|
|
DEBUG1 - 10:54:16.048801144 [15415/15423]: Clean command context structure (in clean_command_ctx() at main.c:641)
|
|
DEBUG1 - 10:54:16.048805850 [15415/15423]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
|
|
DEBUG1 - 10:54:16.048848921 [15415/15423]: Wait for client response (in thread_manage_clients() at main.c:4389)
|
|
DEBUG1 - 10:54:16.048859768 [15415/15423]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
|
|
DEBUG1 - 10:54:16.048871825 [15415/15423]: Processing client command 17 (in process_client_msg() at main.c:2877)
|
|
DEBUG1 - 10:54:16.048875677 [15415/15423]: Getting session auto-20200115-105324 by name (in process_client_msg() at main.c:2970)
|
|
DEBUG2 - 10:54:16.048878849 [15415/15423]: Trying to find session by name auto-20200115-105324 (in session_find_by_name() at session.c:276)
|
|
DEBUG1 - 10:54:16.048882332 [15415/15423]: Sending response (size: 20, retcode: Tracing has already been stopped (81)) (in thread_manage_clients() at main.c:4484)
|
|
DEBUG1 - 10:54:16.048891974 [15415/15423]: Clean command context structure (in clean_command_ctx() at main.c:641)
|
|
DEBUG1 - 10:54:16.048895282 [15415/15423]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
|
|
DEBUG1 - 10:54:16.048931150 [15415/15423]: Wait for client response (in thread_manage_clients() at main.c:4389)
|
|
DEBUG1 - 10:54:16.048941735 [15415/15423]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
|
|
DEBUG1 - 10:54:16.048950074 [15415/15423]: Processing client command 9 (in process_client_msg() at main.c:2877)
|
|
DEBUG1 - 10:54:16.048953550 [15415/15423]: Getting session auto-20200115-105324 by name (in process_client_msg() at main.c:2970)
|
|
DEBUG2 - 10:54:16.048956611 [15415/15423]: Trying to find session by name auto-20200115-105324 (in session_find_by_name() at session.c:276)
|
|
DEBUG3 - 10:54:16.048960128 [15415/15423]: No kernel session when tearing down session (in kernel_destroy_session() at kernel.c:898)
|
|
DEBUG1 - 10:54:16.048963711 [15415/15423]: Destroy all UST traces (in ust_app_destroy_trace_all() at ust-app.c:4992)
|
|
DEBUG1 - 10:54:16.048967154 [15415/15423]: Destroy tracing for ust app pid 14173 (in destroy_trace() at ust-app.c:4885)
|
|
DEBUG3 - 10:54:16.048972113 [15415/15423]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG3 - 10:54:16.048979015 [15415/15423]: No metadata to push for metadata key 4 (in ust_app_push_metadata() at ust-app.c:579)
|
|
DEBUG3 - 10:54:16.048984892 [15415/15423]: UST app deleting channel channel0 (in delete_ust_app_channel() at ust-app.c:460)
|
|
DEBUG1 - 10:54:16.049130948 [15415/15423]: Destroy tracing for ust app pid 7495 (in destroy_trace() at ust-app.c:4885)
|
|
DEBUG3 - 10:54:16.049137340 [15415/15423]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
|
|
DEBUG3 - 10:54:16.049141342 [15415/15423]: No metadata to push for metadata key 4 (in ust_app_push_metadata() at ust-app.c:579)
|
|
DEBUG3 - 10:54:16.049146482 [15415/15423]: UST app deleting channel channel0 (in delete_ust_app_channel() at ust-app.c:460)
|
|
DEBUG2 - 10:54:16.049315822 [15415/15423]: Trace UST destroy session 0 (in trace_ust_destroy_session() at trace-ust.c:1163)
|
|
DEBUG3 - 10:54:16.049333664 [15415/15423]: Buffer registry per UID destroy with id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_destroy() at buffer-registry.c:678)
|
|
DEBUG2 - 10:54:16.049337819 [15415/15423]: Consumer close metadata channel key 4 (in consumer_close_metadata() at consumer.c:1286)
|
|
DEBUG3 - 10:54:16.049334832 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG1 - 10:54:16.049369354 [16083/16092]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
|
|
DEBUG1 - 10:54:16.049382994 [16083/16092]: UST consumer close metadata key 4 (in close_metadata() at ust-consumer.c:836)
|
|
DEBUG1 - 10:54:16.049387779 [16083/16092]: Closing metadata channel key 4 (in lttng_ustconsumer_close_metadata() at ust-consumer.c:2808)
|
|
DEBUG1 - 10:54:16.049401187 [16083/16092]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
|
|
DEBUG1 - 10:54:16.049402370 [16083/16090]: Metadata poll return from wait with 2 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2284)
|
|
DEBUG1 - 10:54:16.049408108 [15415/15423]: Destroying session auto-20200115-105324 (in session_destroy() at session.c:331)
|
|
DEBUG1 - 10:54:16.049411219 [16083/16090]: Metadata event caught in thread (in consumer_thread_metadata_poll() at consumer.c:2286)
|
|
DEBUG1 - 10:54:16.049416339 [16083/16090]: Metadata fd 43 is hup|err. (in consumer_thread_metadata_poll() at consumer.c:2400)
|
|
DEBUG1 - 10:54:16.049419360 [15415/15423]: Empty ltt_sessions_ht_by_id, destroying it (in del_session_ht() at session.c:240)
|
|
DEBUG1 - 10:54:16.049419952 [16083/16090]: Attempting to flush and consume the UST buffers (in consumer_thread_metadata_poll() at consumer.c:2404)
|
|
DEBUG1 - 10:54:16.049431608 [15415/15423]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
|
|
DEBUG1 - 10:54:16.049436979 [16083/16090]: In UST read_subbuffer (wait_fd: 43, name: metadata) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
|
|
DEBUG1 - 10:54:16.049442436 [15415/15423]: Clean command context structure (in clean_command_ctx() at main.c:641)
|
|
DEBUG1 - 10:54:16.049445947 [15415/15423]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
|
|
DEBUG1 - 10:54:16.049457192 [16083/16090]: Consumer mmap write() ret 4096 (len 4096) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1670)
|
|
DEBUG1 - 10:54:16.049506916 [16083/16090]: In UST read_subbuffer (wait_fd: 43, name: metadata) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
|
|
DEBUG1 - 10:54:16.049521584 [16083/16090]: Closing metadata channel key 4 (in lttng_ustconsumer_close_metadata() at ust-consumer.c:2808)
|
|
DEBUG1 - 10:54:16.049541523 [16083/16090]: Consumer delete channel key 4 (in consumer_del_channel() at consumer.c:363)
|
|
DEBUG1 - 10:54:16.049584919 [16083/16090]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2281)
|
|
DEBUG1 - 10:54:16.049595113 [16083/16891]: Destroying metadata cache (in consumer_metadata_cache_destroy() at consumer-metadata-cache.c:220)
|
|
DEBUG2 - 10:54:16.059116558 [15415/16093]: Trace destroy UST event hello_world:my_first_tracepoint (in trace_ust_destroy_event() at trace-ust.c:1007)
|
|
DEBUG2 - 10:54:16.059127060 [15415/16093]: Trace destroy UST channel channel0 (in _trace_ust_destroy_channel() at trace-ust.c:1072)
|
|
DEBUG3 - 10:54:16.059131398 [15415/16093]: Buffer registry session destroy (in buffer_reg_session_destroy() at buffer-registry.c:597)
|
|
DEBUG3 - 10:54:16.059136057 [15415/16093]: Buffer registry channel destroy with key 0 (in buffer_reg_channel_destroy() at buffer-registry.c:552)
|
|
DEBUG3 - 10:54:16.059140233 [15415/16093]: Buffer registry stream destroy with handle -1 (in buffer_reg_stream_destroy() at buffer-registry.c:500)
|
|
DEBUG1 - 10:54:16.059155785 [16083/16089]: Channel poll return from wait with 2 fd(s) (in consumer_thread_channel_poll() at consumer.c:2879)
|
|
DEBUG1 - 10:54:16.059160010 [15415/16093]: Beginning of waiter wait period (in lttng_waiter_wait() at waiter.c:58)
|
|
DEBUG1 - 10:54:16.059165106 [16083/16089]: Channel event caught in thread (in consumer_thread_channel_poll() at consumer.c:2881)
|
|
DEBUG1 - 10:54:16.059164619 [15415/15422]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
|
|
DEBUG1 - 10:54:16.059171901 [16083/16089]: Channel fd 32 is hup|err. (in consumer_thread_channel_poll() at consumer.c:3025)
|
|
DEBUG1 - 10:54:16.059173741 [15415/15422]: [notification-thread] Handling fd (24) activity (1) (in thread_notification() at notification-thread.c:530)
|
|
DEBUG1 - 10:54:16.059180545 [15415/15422]: [notification-thread] Received remove channel command (in handle_notification_thread_command() at notification-thread-events.c:1306)
|
|
DEBUG1 - 10:54:16.059184831 [15415/15422]: [notification-thread] Removing channel key = 1 in user space domain (in handle_notification_thread_command_remove_channel() at notification-thread-events.c:889)
|
|
DEBUG1 - 10:54:16.059189223 [16083/16089]: Channel poll wait (in consumer_thread_channel_poll() at consumer.c:2875)
|
|
DEBUG1 - 10:54:16.059192498 [16083/16091]: poll num_rdy : 1 (in consumer_thread_data_poll() at consumer.c:2551)
|
|
DEBUG1 - 10:54:16.059199381 [15415/15422]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
|
|
DEBUG1 - 10:54:16.059200440 [16083/16091]: fd 35 is hup|err|nval. Attempting flush and read. (in consumer_thread_data_poll() at consumer.c:2683)
|
|
DEBUG1 - 10:54:16.059201084 [15415/16093]: End of waiter wait period (in lttng_waiter_wait() at waiter.c:101)
|
|
DEBUG1 - 10:54:16.059204748 [16083/16091]: Polling fd 35 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2694)
|
|
DEBUG1 - 10:54:16.059208388 [16083/16091]: polling on 3 fd (in consumer_thread_data_poll() at consumer.c:2544)
|
|
DEBUG1 - 10:54:16.059212819 [16083/16091]: poll num_rdy : 1 (in consumer_thread_data_poll() at consumer.c:2551)
|
|
DEBUG1 - 10:54:16.059216144 [16083/16091]: Normal read on fd 35 (in consumer_thread_data_poll() at consumer.c:2658)
|
|
DEBUG1 - 10:54:16.059219433 [16083/16091]: In UST read_subbuffer (wait_fd: 35, name: channel0_0) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
|
|
DEBUG1 - 10:54:16.059223603 [16083/16091]: Reserving sub buffer failed (everything is normal, it is due to concurrency) [ret: -11] (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2570)
|
|
DEBUG1 - 10:54:16.059227085 [16083/16091]: Polling fd 35 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2694)
|
|
DEBUG1 - 10:54:16.059232037 [16083/16091]: Consumer stream destroy monitored key: 35 (in destroy_close_stream() at consumer-stream.c:265)
|
|
DEBUG1 - 10:54:16.059244566 [16083/16091]: Consumer delete channel key 1 (in consumer_del_channel() at consumer.c:363)
|
|
DEBUG1 - 10:54:16.059272219 [16083/16088]: Signal timer metadata thread teardown (in consumer_timer_thread() at consumer-timer.c:835)
|
|
DEBUG1 - 10:54:16.059278974 [16083/16091]: Updating poll fd array (in update_poll_array() at consumer.c:1091)
|
|
DEBUG1 - 10:54:16.059295170 [16083/16091]: polling on 2 fd (in consumer_thread_data_poll() at consumer.c:2544)
|
|
DEBUG3 - 10:54:16.059446871 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.059513484 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.069603842 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.069616864 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.079689659 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.079707260 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.089799771 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.089818556 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.099907506 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.099922063 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.110007744 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.110019300 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.120106004 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.120119220 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.130216153 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.130231257 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.140279629 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.140292964 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.150386560 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.150398421 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.160477437 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.160488283 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.170572190 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.170587772 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.180674573 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.180687797 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.190742705 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.190774064 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.200834714 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.200846827 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.210934887 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.210951282 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.221039443 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|
|
DEBUG3 - 10:54:16.221055320 [15415/15419]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
|
|
DEBUG3 - 10:54:16.231137925 [15415/15419]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
|