[lttng-dev] Wrong timestamps in trace
Thomas McGuire
thomas.mcguire at kdab.com
Mon Jun 12 15:21:07 UTC 2017
Hi,
I'm struggling to get lttng to run on an i.MX 25 board. I got everything
working, however the timestamps in the resulting trace file are all the
same. Because of the timestamps, TraceCompass fails at visualizing the
schedule.
I record on the device and then copy the trace over to my host to
examine it with babeltrace. See attached text files for the start and
the end of the trace, showing the timestamps being the same, despite the
trace running for a few seconds.
The output of lttng-sessiond -v is also attached.
I started everything the following way:
cd /lib/modules/4.9.28-20170428-1/kernel/extra
find . -type f -exec insmod {} \;
find . -type f -exec insmod {} \;
find . -type f -exec insmod {} \;
find . -type f -exec insmod {} \;
lttng-sessiond -v --consumerd32-path=/usr/bin/lttng-consumerd &>
sessiond-log.txt
lttng create my-session --output=/home/lttng/my-trace
lttng enable-event --kernel --syscall --all --channel channel0
lttng enable-event --kernel --channel channel0 sched*
lttng start
sleep 5 # do something
lttng stop
The Linux distribution is Pengutronix's ptxdist, which doesn't have
lttng rules, so I manually cross-compiled lttng-tools 2.9.4 and
lttng-modules 2.9.2. Kernel is 4.9.28-20170428-1, babeltrace on the host
is 1.2.4.
What do I need to do to get correct timestamps?
Thanks,
Thomas
--
Thomas McGuire | thomas.mcguire at kdab.com | Senior Software Engineer
KDAB (Deutschland) GmbH&Co KG, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt Experts
-------------- next part --------------
[16:58:21.198000128] (+?.?????????) MySystem sched_waking: { cpu_id = 0 }, { comm = "lttng-consumerd", tid = 2536, prio = 20, target_cpu = 0 }
[16:58:21.198000128] (+0.000000000) MySystem sched_stat_runtime: { cpu_id = 0 }, { comm = "lttng-sessiond", tid = 2518, runtime = 4630452, vruntime = 372882775872 }
[16:58:21.198000128] (+0.000000000) MySystem sched_wakeup: { cpu_id = 0 }, { comm = "lttng-consumerd", tid = 2536, prio = 20, target_cpu = 0 }
[16:58:21.198000128] (+0.000000000) MySystem sched_switch: { cpu_id = 0 }, { prev_comm = "lttng-sessiond", prev_tid = 2518, prev_prio = 20, prev_state = 4096, next_comm = "lttng-consumerd", next_tid = 2536, next_prio = 20 }
[16:58:21.198000128] (+0.000000000) MySystem syscall_exit_restart_syscall: { cpu_id = 0 }, { ret = 1 }
[16:58:21.198000128] (+0.000000000) MySystem sched_stat_runtime: { cpu_id = 0 }, { comm = "lttng-consumerd", tid = 2536, runtime = 395819, vruntime = 372880171691 }
[16:58:21.198000128] (+0.000000000) MySystem syscall_entry_ioctl: { cpu_id = 0 }, { fd = 26, cmd = 62981, arg = 2536 }
[16:58:21.198000128] (+0.000000000) MySystem syscall_exit_ioctl: { cpu_id = 0 }, { ret = 0, arg = 2536 }
[16:58:21.198000128] (+0.000000000) MySystem syscall_entry_ioctl: { cpu_id = 0 }, { fd = 26, cmd = 2147808776, arg = 3046107820 }
[16:58:21.198000128] (+0.000000000) MySystem syscall_exit_ioctl: { cpu_id = 0 }, { ret = 0, arg = 3046107820 }
-------------- next part --------------
[16:58:21.198000128] (+0.000000000) MySystem syscall_exit_gettid: { cpu_id = 0 }, { ret = 2518 }
[16:58:21.198000128] (+0.000000000) MySystem syscall_entry_write: { cpu_id = 0 }, { fd = 2, buf = 3045881288, count = 114 }
[16:58:21.198000128] (+0.000000000) MySystem syscall_exit_write: { cpu_id = 0 }, { ret = 114 }
[16:58:21.198000128] (+0.000000000) MySystem syscall_entry_clock_gettime: { cpu_id = 0 }, { which_clock = 0 }
[16:58:21.198000128] (+0.000000000) MySystem syscall_exit_clock_gettime: { cpu_id = 0 }, { ret = 0, tp = 3045890724 }
[16:58:21.198000128] (+0.000000000) MySystem syscall_entry_gettid: { cpu_id = 0 }, { }
[16:58:21.198000128] (+0.000000000) MySystem syscall_exit_gettid: { cpu_id = 0 }, { ret = 2518 }
[16:58:21.198000128] (+0.000000000) MySystem syscall_entry_write: { cpu_id = 0 }, { fd = 2, buf = 3045881248, count = 94 }
[16:58:21.198000128] (+0.000000000) MySystem syscall_exit_write: { cpu_id = 0 }, { ret = 94 }
[16:58:21.198000128] (+0.000000000) MySystem syscall_entry_ioctl: { cpu_id = 0 }, { fd = 31, cmd = 63063, arg = 0 }
-------------- next part --------------
DEBUG1 - 16:57:37.872169 [2515/2515]: Resetting run_as worker signal handlers to default (in reset_sighandler() at runas.c:537)
DEBUG1 - 16:57:37.878774 [2515/2515]: run_as signal handler set for SIGTERM and SIGINT (in set_worker_sighandlers() at runas.c:598)
DEBUG1 - 16:57:37.880616 [2514/2514]: Health check time delta in seconds set to 20 (in health_init() at health.c:73)
DEBUG1 - 16:57:37.889119 [2514/2514]: Client socket path /var/run/lttng/client-lttng-sessiond (in main() at main.c:5771)
DEBUG1 - 16:57:37.890097 [2514/2514]: Application socket path /var/run/lttng/lttng-ust-sock-7 (in main() at main.c:5772)
DEBUG1 - 16:57:37.890288 [2514/2514]: Application wait path /lttng-ust-wait-7 (in main() at main.c:5773)
DEBUG1 - 16:57:37.890489 [2514/2514]: LTTng run directory path: /var/run/lttng (in main() at main.c:5774)
DEBUG1 - 16:57:37.886879 [2514/2516]: [ht-thread] startup. (in thread_ht_cleanup() at ht-cleanup.c:101)
DEBUG1 - 16:57:37.896143 [2514/2516]: epoll set max size is 42690 (in compat_epoll_set_max_size() at compat-epoll.c:288)
Warning: No tracing group detected
DEBUG1 - 16:57:37.923635 [2514/2514]: Modprobe successfully lttng-ring-buffer-client-discard (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.924979 [2514/2514]: Modprobe successfully lttng-ring-buffer-client-overwrite (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.925797 [2514/2514]: Modprobe successfully lttng-ring-buffer-metadata-client (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.926618 [2514/2514]: Modprobe successfully lttng-ring-buffer-client-mmap-discard (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.927405 [2514/2514]: Modprobe successfully lttng-ring-buffer-client-mmap-overwrite (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.928171 [2514/2514]: Modprobe successfully lttng-ring-buffer-metadata-mmap-client (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.942720 [2514/2514]: Unable to load optional module lttng-probe-asoc; continuing (in modprobe_lttng() at modprobe.c:196)
DEBUG1 - 16:57:37.943579 [2514/2514]: Modprobe successfully lttng-probe-block (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.945282 [2514/2514]: Unable to load optional module lttng-probe-btrfs; continuing (in modprobe_lttng() at modprobe.c:196)
DEBUG1 - 16:57:37.946128 [2514/2514]: Modprobe successfully lttng-probe-compaction (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.947442 [2514/2514]: Unable to load optional module lttng-probe-ext3; continuing (in modprobe_lttng() at modprobe.c:196)
DEBUG1 - 16:57:37.948271 [2514/2514]: Modprobe successfully lttng-probe-ext4 (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.949040 [2514/2514]: Modprobe successfully lttng-probe-gpio (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.950164 [2514/2514]: Modprobe successfully lttng-probe-i2c (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.950987 [2514/2514]: Modprobe successfully lttng-probe-irq (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.952291 [2514/2514]: Unable to load optional module lttng-probe-jbd; continuing (in modprobe_lttng() at modprobe.c:196)
DEBUG1 - 16:57:37.953093 [2514/2514]: Modprobe successfully lttng-probe-jbd2 (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.953873 [2514/2514]: Modprobe successfully lttng-probe-kmem (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.955550 [2514/2514]: Unable to load optional module lttng-probe-kvm; continuing (in modprobe_lttng() at modprobe.c:196)
DEBUG1 - 16:57:37.956901 [2514/2514]: Unable to load optional module lttng-probe-kvm-x86; continuing (in modprobe_lttng() at modprobe.c:196)
DEBUG1 - 16:57:37.958217 [2514/2514]: Unable to load optional module lttng-probe-kvm-x86-mmu; continuing (in modprobe_lttng() at modprobe.c:196)
DEBUG1 - 16:57:37.960013 [2514/2514]: Unable to load optional module lttng-probe-lock; continuing (in modprobe_lttng() at modprobe.c:196)
DEBUG1 - 16:57:37.960875 [2514/2514]: Modprobe successfully lttng-probe-module (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.961651 [2514/2514]: Modprobe successfully lttng-probe-napi (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.962576 [2514/2514]: Modprobe successfully lttng-probe-net (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.963400 [2514/2514]: Modprobe successfully lttng-probe-power (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.964167 [2514/2514]: Modprobe successfully lttng-probe-printk (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.965419 [2514/2514]: Modprobe successfully lttng-probe-random (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.966236 [2514/2514]: Modprobe successfully lttng-probe-rcu (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.967011 [2514/2514]: Modprobe successfully lttng-probe-regmap (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.967803 [2514/2514]: Modprobe successfully lttng-probe-regulator (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.969099 [2514/2514]: Unable to load optional module lttng-probe-rpm; continuing (in modprobe_lttng() at modprobe.c:196)
DEBUG1 - 16:57:37.970623 [2514/2514]: Modprobe successfully lttng-probe-sched (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.971460 [2514/2514]: Modprobe successfully lttng-probe-scsi (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.972212 [2514/2514]: Modprobe successfully lttng-probe-signal (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.972980 [2514/2514]: Modprobe successfully lttng-probe-skb (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.973776 [2514/2514]: Modprobe successfully lttng-probe-sock (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.974865 [2514/2514]: Modprobe successfully lttng-probe-statedump (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.975801 [2514/2514]: Modprobe successfully lttng-probe-sunrpc (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.976600 [2514/2514]: Modprobe successfully lttng-probe-timer (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.977410 [2514/2514]: Modprobe successfully lttng-probe-udp (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.978181 [2514/2514]: Modprobe successfully lttng-probe-vmscan (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.979856 [2514/2514]: Unable to load optional module lttng-probe-v4l2; continuing (in modprobe_lttng() at modprobe.c:196)
DEBUG1 - 16:57:37.980737 [2514/2514]: Modprobe successfully lttng-probe-workqueue (in modprobe_lttng() at modprobe.c:200)
DEBUG1 - 16:57:37.982045 [2514/2514]: Unable to load optional module lttng-probe-writeback; continuing (in modprobe_lttng() at modprobe.c:196)
DEBUG1 - 16:57:37.983402 [2514/2514]: Unable to load optional module lttng-probe-x86-irq-vectors; continuing (in modprobe_lttng() at modprobe.c:196)
DEBUG1 - 16:57:37.985376 [2514/2514]: Unable to load optional module lttng-probe-x86-exceptions; continuing (in modprobe_lttng() at modprobe.c:196)
DEBUG1 - 16:57:37.986272 [2514/2514]: Kernel tracer fd 13 (in init_kernel_tracer() at main.c:2731)
DEBUG1 - 16:57:38.163161 [2514/2514]: Reallocating syscall table from 256 to 512 entries (in syscall_init_table() at syscall.c:95)
DEBUG1 - 16:57:38.234602 [2514/2514]: All permissions are set (in set_permissions() at main.c:5254)
DEBUG1 - 16:57:38.240811 [2514/2514]: Command subsystem initialized (in cmd_init() at cmd.c:4006)
DEBUG1 - 16:57:38.252828 [2514/2514]: Pid 2514 written in file /var/run/lttng/lttng-sessiond.pid (in utils_create_pid_file() at utils.c:507)
DEBUG1 - 16:57:38.261866 [2514/2514]: Pid 5345 written in file /var/run/lttng/agent.port (in utils_create_pid_file() at utils.c:507)
DEBUG1 - 16:57:38.269559 [2514/2514]: TCP inet operation timeout set to 216 sec (in lttcomm_inet_init() at inet.c:547)
DEBUG1 - 16:57:38.328981 [2514/2518]: [thread] Manage client started (in thread_manage_clients() at main.c:4348)
DEBUG1 - 16:57:38.341568 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:57:38.347180 [2514/2519]: [thread] Dispatch UST command started (in thread_dispatch_ust_registration() at main.c:1870)
DEBUG1 - 16:57:38.379738 [2514/2519]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
DEBUG1 - 16:57:38.382091 [2514/2519]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1893)
DEBUG1 - 16:57:38.350387 [2514/2517]: [thread] Manage health check started (in thread_manage_health() at main.c:4157)
DEBUG1 - 16:57:38.353961 [2514/2520]: [thread] Manage application registration started (in thread_registration_apps() at main.c:2111)
DEBUG1 - 16:57:38.404037 [2514/2520]: Notifying applications of session daemon state: 1 (in notify_ust_apps() at main.c:805)
DEBUG1 - 16:57:38.417501 [2514/2520]: Got the wait shm fd 28 (in get_wait_shm() at shm.c:115)
DEBUG1 - 16:57:38.424276 [2514/2520]: Futex wait update active 1 (in futex_wait_update() at futex.c:65)
DEBUG1 - 16:57:38.427074 [2514/2520]: Accepting application registration (in thread_registration_apps() at main.c:2148)
DEBUG1 - 16:57:38.363783 [2514/2521]: [thread] Manage application started (in thread_manage_apps() at main.c:1556)
DEBUG1 - 16:57:38.433098 [2514/2521]: Apps thread polling (in thread_manage_apps() at main.c:1586)
DEBUG1 - 16:57:38.371723 [2514/2524]: [thread] Thread manage kernel started (in thread_manage_kernel() at main.c:1054)
DEBUG1 - 16:57:38.449291 [2514/2524]: Updating kernel poll set (in update_kernel_poll() at main.c:889)
DEBUG1 - 16:57:38.451793 [2514/2524]: Thread kernel polling (in thread_manage_kernel() at main.c:1099)
DEBUG1 - 16:57:38.454696 [2514/2525]: [load-session-thread] Load session (in thread_load_session() at load-session-thread.c:91)
DEBUG1 - 16:57:38.521521 [2514/2517]: Health check ready (in thread_manage_health() at main.c:4219)
DEBUG1 - 16:57:48.677245 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:57:48.679825 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:57:48.681454 [2514/2518]: Processing client command 13 (in process_client_msg() at main.c:2983)
DEBUG1 - 16:57:48.681911 [2514/2518]: Counting number of available session for UID 0 GID 0 (in lttng_sessions_count() at main.c:2952)
DEBUG1 - 16:57:48.682132 [2514/2518]: Getting all available session for UID 0 GID 0 (in cmd_list_lttng_sessions() at cmd.c:3040)
DEBUG1 - 16:57:48.682389 [2514/2518]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4542)
DEBUG1 - 16:57:48.683051 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:57:48.683300 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:57:57.562832 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:57:57.563465 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:57:57.564058 [2514/2518]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:4496)
DEBUG1 - 16:57:57.564782 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:57:57.565035 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:57:57.573213 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:57:57.573834 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:57:57.575514 [2514/2518]: Processing client command 8 (in process_client_msg() at main.c:2983)
DEBUG1 - 16:57:57.575950 [2514/2518]: Waiting for 1 URIs from client ... (in process_client_msg() at main.c:3759)
DEBUG1 - 16:57:57.577260 [2514/2518]: Allocating ltt_sessions_ht_by_id (in ltt_sessions_ht_alloc() at session.c:153)
DEBUG1 - 16:57:57.577684 [2514/2518]: Tracing session my-session created with ID 0 by UID 0 GID 0 (in session_create() at session.c:420)
DEBUG1 - 16:57:57.578484 [2514/2518]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4542)
DEBUG1 - 16:57:57.578929 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:57:57.579297 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:58:04.192924 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:58:04.193574 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:58:04.195028 [2514/2518]: Processing client command 14 (in process_client_msg() at main.c:2983)
DEBUG1 - 16:58:04.198970 [2514/2518]: Reallocating event list from 64 to 128 bytes (in kernel_list_events() at kernel.c:766)
DEBUG1 - 16:58:04.203971 [2514/2518]: Reallocating event list from 128 to 256 bytes (in kernel_list_events() at kernel.c:766)
DEBUG1 - 16:58:04.215023 [2514/2518]: Reallocating event list from 256 to 512 bytes (in kernel_list_events() at kernel.c:766)
DEBUG1 - 16:58:04.220543 [2514/2518]: Kernel list events done (264 events) (in kernel_list_events() at kernel.c:789)
DEBUG1 - 16:58:04.227327 [2514/2518]: Sending response (size: 154196, retcode: Success (10)) (in thread_manage_clients() at main.c:4542)
DEBUG1 - 16:58:04.233616 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:58:04.234211 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:58:08.166368 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:58:08.167006 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:58:08.168368 [2514/2518]: Processing client command 6 (in process_client_msg() at main.c:2983)
DEBUG1 - 16:58:08.168654 [2514/2518]: Getting session my-session by name (in process_client_msg() at main.c:3072)
DEBUG1 - 16:58:08.168891 [2514/2518]: Creating kernel session (in create_kernel_session() at main.c:2899)
DEBUG1 - 16:58:08.170167 [2514/2518]: Kernel session created (fd: 31) (in kernel_create_session() at kernel.c:111)
DEBUG1 - 16:58:08.172434 [2514/2518]: Using run_as worker (in run_as() at runas.c:451)
DEBUG1 - 16:58:08.181965 [2514/2518]: Spawning consumerd (in spawn_consumerd() at main.c:2488)
DEBUG1 - 16:58:08.195162 [2514/2532]: [thread] Manage consumer started (in thread_manage_consumer() at main.c:1228)
DEBUG1 - 16:58:08.196739 [2531/2531]: Using kernel consumer at: /usr/bin/lttng-consumerd (in spawn_consumerd() at main.c:2528)
Warning: No tracing group detected
DEBUG1 - 16:58:08.385665 [2514/2518]: Setting relayd for session my-session (in cmd_setup_relayd() at cmd.c:1010)
DEBUG1 - 16:58:08.386040 [2514/2518]: Enable event command for event '*' (in _cmd_enable_event() at cmd.c:1818)
DEBUG1 - 16:58:08.386253 [2514/2518]: Trying to find channel channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:48)
DEBUG1 - 16:58:08.386625 [2514/2518]: Enabling channel channel0 for session my-session (in cmd_enable_channel() at cmd.c:1313)
DEBUG1 - 16:58:08.386838 [2514/2518]: Trying to find channel channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:48)
DEBUG1 - 16:58:08.389626 [2514/2532]: Consumer command socket ready (fd: 34 (in thread_manage_consumer() at main.c:1359)
DEBUG1 - 16:58:08.389891 [2514/2532]: Consumer metadata socket ready (fd: 35) (in thread_manage_consumer() at main.c:1361)
DEBUG1 - 16:58:08.406193 [2514/2518]: Kernel channel channel0 created (fd: 36) (in kernel_create_channel() at kernel.c:167)
DEBUG1 - 16:58:08.406741 [2514/2524]: Thread kernel return from poll on 2 fds (in thread_manage_kernel() at main.c:1106)
DEBUG1 - 16:58:08.407315 [2514/2524]: Updating kernel poll set (in update_kernel_poll() at main.c:889)
DEBUG1 - 16:58:08.407700 [2514/2518]: Kernel quiescent wait on 13 (in kernel_wait_quiescent() at kernel.c:570)
DEBUG1 - 16:58:08.407986 [2514/2518]: Trying to find channel channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:48)
DEBUG1 - 16:58:08.408191 [2514/2518]: Found channel by name channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:52)
DEBUG1 - 16:58:08.408588 [2514/2518]: Event * created (fd: 37) (in kernel_create_event() at kernel.c:252)
DEBUG1 - 16:58:08.408920 [2514/2518]: Kernel quiescent wait on 13 (in kernel_wait_quiescent() at kernel.c:570)
DEBUG1 - 16:58:08.409551 [2514/2524]: Channel fd 36 added to kernel set (in update_kernel_poll() at main.c:907)
DEBUG1 - 16:58:08.409848 [2514/2524]: Thread kernel polling (in thread_manage_kernel() at main.c:1099)
DEBUG1 - 16:58:08.410075 [2514/2524]: Thread kernel return from poll on 3 fds (in thread_manage_kernel() at main.c:1106)
DEBUG1 - 16:58:08.410307 [2514/2524]: Updating kernel streams for channel fd 36 (in update_kernel_stream() at main.c:933)
DEBUG1 - 16:58:08.410485 [2514/2524]: Channel found, updating kernel streams (in update_kernel_stream() at main.c:952)
DEBUG1 - 16:58:08.410821 [2514/2524]: Kernel stream channel0_0 created (fd: 38, state: 0) (in kernel_open_channel_stream() at kernel.c:684)
DEBUG1 - 16:58:08.411160 [2514/2524]: Thread kernel polling (in thread_manage_kernel() at main.c:1099)
DEBUG1 - 16:58:08.411586 [2514/2518]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4542)
DEBUG1 - 16:58:08.427173 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:58:08.427589 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:58:13.237217 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:58:13.237944 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:58:13.239261 [2514/2518]: Processing client command 6 (in process_client_msg() at main.c:2983)
DEBUG1 - 16:58:13.239842 [2514/2518]: Getting session my-session by name (in process_client_msg() at main.c:3072)
DEBUG1 - 16:58:13.240125 [2514/2518]: Setting relayd for session my-session (in cmd_setup_relayd() at cmd.c:1010)
DEBUG1 - 16:58:13.240324 [2514/2518]: Enable event command for event 'sched*' (in _cmd_enable_event() at cmd.c:1818)
DEBUG1 - 16:58:13.240555 [2514/2518]: Trying to find channel channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:48)
DEBUG1 - 16:58:13.240727 [2514/2518]: Found channel by name channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:52)
DEBUG1 - 16:58:13.240886 [2514/2518]: Trying to find channel channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:48)
DEBUG1 - 16:58:13.241087 [2514/2518]: Found channel by name channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:52)
DEBUG1 - 16:58:13.241411 [2514/2518]: Event sched* created (fd: 39) (in kernel_create_event() at kernel.c:252)
DEBUG1 - 16:58:13.241665 [2514/2518]: Kernel quiescent wait on 13 (in kernel_wait_quiescent() at kernel.c:570)
DEBUG1 - 16:58:13.241881 [2514/2518]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4542)
DEBUG1 - 16:58:13.242283 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:58:13.242517 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:58:18.339178 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:58:18.339987 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:58:18.341391 [2514/2518]: Processing client command 13 (in process_client_msg() at main.c:2983)
DEBUG1 - 16:58:18.341662 [2514/2518]: Counting number of available session for UID 0 GID 0 (in lttng_sessions_count() at main.c:2952)
DEBUG1 - 16:58:18.342013 [2514/2518]: Getting all available session for UID 0 GID 0 (in cmd_list_lttng_sessions() at cmd.c:3040)
DEBUG1 - 16:58:18.342500 [2514/2518]: Sending response (size: 4396, retcode: Success (10)) (in thread_manage_clients() at main.c:4542)
DEBUG1 - 16:58:18.342998 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:58:18.343254 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:58:18.349219 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:58:18.350148 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:58:18.351422 [2514/2518]: Processing client command 11 (in process_client_msg() at main.c:2983)
DEBUG1 - 16:58:18.351740 [2514/2518]: Getting session my-session by name (in process_client_msg() at main.c:3072)
DEBUG1 - 16:58:18.352007 [2514/2518]: Sending response (size: 328, retcode: Success (10)) (in thread_manage_clients() at main.c:4542)
DEBUG1 - 16:58:18.352444 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:58:18.352720 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:58:18.361805 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:58:18.362428 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:58:18.365823 [2514/2518]: Processing client command 34 (in process_client_msg() at main.c:2983)
DEBUG1 - 16:58:18.366124 [2514/2518]: Getting session my-session by name (in process_client_msg() at main.c:3072)
DEBUG1 - 16:58:18.366357 [2514/2518]: Setting relayd for session my-session (in cmd_setup_relayd() at cmd.c:1010)
DEBUG1 - 16:58:18.366889 [2514/2518]: Kernel list tracker pids done (1 pids) (in kernel_list_tracker_pids() at kernel.c:481)
DEBUG1 - 16:58:18.367285 [2514/2518]: Sending response (size: 24, retcode: Success (10)) (in thread_manage_clients() at main.c:4542)
DEBUG1 - 16:58:18.367730 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:58:18.367967 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:58:18.370015 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:58:18.370653 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:58:18.371782 [2514/2518]: Processing client command 10 (in process_client_msg() at main.c:2983)
DEBUG1 - 16:58:18.372088 [2514/2518]: Getting session my-session by name (in process_client_msg() at main.c:3072)
DEBUG1 - 16:58:18.372324 [2514/2518]: Setting relayd for session my-session (in cmd_setup_relayd() at cmd.c:1010)
DEBUG1 - 16:58:18.372584 [2514/2518]: Listing channels for session my-session (in list_lttng_channels() at cmd.c:245)
DEBUG1 - 16:58:18.372844 [2514/2518]: Sending response (size: 660, retcode: Success (10)) (in thread_manage_clients() at main.c:4542)
DEBUG1 - 16:58:18.373267 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:58:18.373503 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:58:18.385357 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:58:18.385987 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:58:18.386697 [2514/2518]: Processing client command 12 (in process_client_msg() at main.c:2983)
DEBUG1 - 16:58:18.386950 [2514/2518]: Getting session my-session by name (in process_client_msg() at main.c:3072)
DEBUG1 - 16:58:18.387199 [2514/2518]: Setting relayd for session my-session (in cmd_setup_relayd() at cmd.c:1010)
DEBUG1 - 16:58:18.387402 [2514/2518]: Trying to find channel channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:48)
DEBUG1 - 16:58:18.387588 [2514/2518]: Found channel by name channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:52)
DEBUG1 - 16:58:18.387789 [2514/2518]: Listing events for channel channel0 (in list_lttng_kernel_events() at cmd.c:601)
DEBUG1 - 16:58:18.388081 [2514/2518]: Sending response (size: 1208, retcode: Success (10)) (in thread_manage_clients() at main.c:4542)
DEBUG1 - 16:58:18.388517 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:58:18.388750 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:58:20.995375 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:58:20.995998 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:58:20.997286 [2514/2518]: Processing client command 16 (in process_client_msg() at main.c:2983)
DEBUG1 - 16:58:20.997606 [2514/2518]: Getting session my-session by name (in process_client_msg() at main.c:3072)
DEBUG1 - 16:58:21.631670 [2514/2518]: Kernel metadata opened (fd: 40) (in kernel_open_metadata() at kernel.c:530)
DEBUG1 - 16:58:21.666542 [2514/2518]: Kernel metadata stream created (fd: 41) (in kernel_open_metadata_stream() at kernel.c:708)
DEBUG1 - 16:58:21.715444 [2514/2518]: Sending session stream to kernel consumer (in kernel_consumer_send_session() at kernel-consumer.c:383)
DEBUG1 - 16:58:21.741804 [2514/2518]: Sending metadata 41 to kernel consumer (in kernel_consumer_add_metadata() at kernel-consumer.c:167)
DEBUG1 - 16:58:21.810611 [2514/2518]: Using run_as worker (in run_as() at runas.c:451)
DEBUG1 - 16:58:21.334064 [2514/2518]: Sending streams of channel channel0 to kernel consumer (in kernel_consumer_send_channel_stream() at kernel-consumer.c:332)
DEBUG1 - 16:58:21.337103 [2514/2518]: Kernel consumer adding channel channel0 to kernel consumer (in kernel_consumer_add_channel() at kernel-consumer.c:106)
DEBUG1 - 16:58:21.340426 [2514/2518]: Using run_as worker (in run_as() at runas.c:451)
DEBUG1 - 16:58:21.402148 [2514/2518]: Sending stream 38 of channel channel0 to kernel consumer (in kernel_consumer_add_stream() at kernel-consumer.c:249)
DEBUG1 - 16:58:21.476319 [2514/2518]: Sending streams_sent (in kernel_consumer_streams_sent() at kernel-consumer.c:288)
DEBUG1 - 16:58:21.709845 [2514/2518]: Kernel consumer FDs of metadata and channel streams sent (in kernel_consumer_send_session() at kernel-consumer.c:411)
DEBUG1 - 16:58:21.584998 [2514/2518]: Kernel session started (in kernel_start_session() at kernel.c:555)
DEBUG1 - 16:58:21.585415 [2514/2518]: Kernel quiescent wait on 13 (in kernel_wait_quiescent() at kernel.c:570)
DEBUG1 - 16:58:21.585819 [2514/2518]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4542)
DEBUG1 - 16:58:21.622878 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:58:21.623301 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:58:34.508416 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:58:34.509266 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:58:34.511429 [2514/2518]: Processing client command 17 (in process_client_msg() at main.c:2983)
DEBUG1 - 16:58:34.511859 [2514/2518]: Getting session my-session by name (in process_client_msg() at main.c:3072)
DEBUG1 - 16:58:34.512218 [2514/2518]: Stop kernel tracing (in cmd_stop_trace() at cmd.c:2438)
DEBUG1 - 16:58:34.523677 [2514/2518]: Kernel session stopped (in kernel_stop_session() at kernel.c:635)
DEBUG1 - 16:58:34.524024 [2514/2518]: Kernel quiescent wait on 13 (in kernel_wait_quiescent() at kernel.c:570)
DEBUG1 - 16:58:34.524299 [2514/2518]: Kernel flushing metadata buffer on fd 41 (in kernel_metadata_flush_buffer() at kernel.c:586)
DEBUG1 - 16:58:34.524900 [2514/2518]: Flush buffer for channel channel0 (in kernel_flush_buffer() at kernel.c:606)
DEBUG1 - 16:58:34.525160 [2514/2518]: Flushing channel stream 38 (in kernel_flush_buffer() at kernel.c:609)
DEBUG1 - 16:58:34.525423 [2514/2518]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4542)
DEBUG1 - 16:58:34.529973 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:58:34.530301 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:58:34.530614 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:58:34.531227 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:58:34.532245 [2514/2518]: Processing client command 24 (in process_client_msg() at main.c:2983)
DEBUG1 - 16:58:34.532551 [2514/2518]: Getting session my-session by name (in process_client_msg() at main.c:3072)
DEBUG1 - 16:58:34.534973 [2514/2518]: Consumer data is pending for session id 0 (in consumer_is_data_pending() at consumer.c:1154)
DEBUG1 - 16:58:34.535373 [2514/2518]: Sending response (size: 21, retcode: Success (10)) (in thread_manage_clients() at main.c:4542)
DEBUG1 - 16:58:34.536617 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:58:34.536982 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:58:34.741375 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:58:34.742073 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:58:34.742872 [2514/2518]: Processing client command 24 (in process_client_msg() at main.c:2983)
DEBUG1 - 16:58:34.743170 [2514/2518]: Getting session my-session by name (in process_client_msg() at main.c:3072)
DEBUG1 - 16:58:34.746722 [2514/2518]: Consumer data is NOT pending for session id 0 (in consumer_is_data_pending() at consumer.c:1154)
DEBUG1 - 16:58:34.747133 [2514/2518]: Sending response (size: 21, retcode: Success (10)) (in thread_manage_clients() at main.c:4542)
DEBUG1 - 16:58:34.751514 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:58:34.751875 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:58:34.752163 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:58:34.752769 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:58:34.753687 [2514/2518]: Processing client command 11 (in process_client_msg() at main.c:2983)
DEBUG1 - 16:58:34.754033 [2514/2518]: Getting session my-session by name (in process_client_msg() at main.c:3072)
DEBUG1 - 16:58:34.754659 [2514/2518]: Sending response (size: 328, retcode: Success (10)) (in thread_manage_clients() at main.c:4542)
DEBUG1 - 16:58:34.756899 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:58:34.757221 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 16:58:34.757533 [2514/2518]: Wait for client response (in thread_manage_clients() at main.c:4447)
DEBUG1 - 16:58:34.758127 [2514/2518]: Receiving data from client ... (in thread_manage_clients() at main.c:4492)
DEBUG1 - 16:58:34.759031 [2514/2518]: Processing client command 10 (in process_client_msg() at main.c:2983)
DEBUG1 - 16:58:34.759327 [2514/2518]: Getting session my-session by name (in process_client_msg() at main.c:3072)
DEBUG1 - 16:58:34.759995 [2514/2518]: Setting relayd for session my-session (in cmd_setup_relayd() at cmd.c:1010)
DEBUG1 - 16:58:34.760284 [2514/2518]: Listing channels for session my-session (in list_lttng_channels() at cmd.c:245)
DEBUG1 - 16:58:34.761892 [2514/2518]: Consumer discarded 0 events in session id 0 (in consumer_get_discarded_events() at consumer.c:1465)
DEBUG1 - 16:58:34.763621 [2514/2518]: Consumer lost 0 packets in session id 0 (in consumer_get_lost_packets() at consumer.c:1522)
DEBUG1 - 16:58:34.764063 [2514/2518]: Sending response (size: 660, retcode: Success (10)) (in thread_manage_clients() at main.c:4542)
DEBUG1 - 16:58:34.777847 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 16:58:34.778175 [2514/2518]: Accepting client command ... (in thread_manage_clients() at main.c:4395)
DEBUG1 - 17:09:17.534551 [2515/2515]: run_as worker received signal SIGINT (in worker_sighandler() at runas.c:567)
DEBUG1 - 17:09:17.535411 [2514/2514]: SIGINT caught (in sighandler() at main.c:5370)
DEBUG1 - 17:09:17.535897 [2514/2514]: Terminating all threads (in stop_threads() at main.c:470)
DEBUG1 - 17:09:17.536517 [2514/2524]: Thread kernel return from poll on 3 fds (in thread_manage_kernel() at main.c:1106)
DEBUG1 - 17:09:17.537114 [2514/2524]: Kernel thread dying (in thread_manage_kernel() at main.c:1190)
DEBUG1 - 17:09:17.540126 [2514/2517]: Health check thread dying (in thread_manage_health() at main.c:4321)
DEBUG1 - 17:09:17.541174 [2514/2521]: Apps thread return from poll on 2 fds (in thread_manage_apps() at main.c:1593)
DEBUG1 - 17:09:17.541818 [2514/2521]: Application communication apps thread cleanup complete (in thread_manage_apps() at main.c:1701)
DEBUG1 - 17:09:17.542692 [2514/2520]: Notifying applications of session daemon state: 0 (in notify_ust_apps() at main.c:805)
DEBUG1 - 17:09:17.543430 [2514/2520]: Got the wait shm fd 11 (in get_wait_shm() at shm.c:115)
DEBUG1 - 17:09:17.544467 [2514/2518]: Clean command context structure (in clean_command_ctx() at main.c:785)
DEBUG1 - 17:09:17.554936 [2514/2519]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105)
DEBUG1 - 17:09:17.555431 [2514/2519]: Dispatch thread dying (in thread_dispatch_ust_registration() at main.c:2087)
DEBUG1 - 17:09:17.556130 [2514/2514]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
DEBUG1 - 17:09:17.558284 [2514/2518]: Client thread dying (in thread_manage_clients() at main.c:4589)
DEBUG1 - 17:09:17.543997 [2514/2520]: Futex wait update active 0 (in futex_wait_update() at futex.c:65)
DEBUG1 - 17:09:17.561875 [2514/2520]: UST Registration thread cleanup complete (in thread_registration_apps() at main.c:2313)
DEBUG1 - 17:09:17.564950 [2514/2517]: Terminating all threads (in stop_threads() at main.c:470)
DEBUG1 - 17:09:17.565312 [2514/2517]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
DEBUG1 - 17:09:17.564070 [2514/2532]: consumer thread cleanup completed (in thread_manage_consumer() at main.c:1538)
DEBUG1 - 17:09:17.568934 [2514/2514]: Cleanup sessiond (in sessiond_cleanup() at main.c:584)
DEBUG1 - 17:09:17.570023 [2514/2514]: Removing sessiond and consumerd content of directory /var/run/lttng (in sessiond_cleanup() at main.c:603)
DEBUG1 - 17:09:17.570365 [2514/2514]: Removing /var/run/lttng/lttng-sessiond.pid (in sessiond_cleanup() at main.c:609)
DEBUG1 - 17:09:17.570961 [2514/2514]: Removing /var/run/lttng/agent.port (in sessiond_cleanup() at main.c:614)
DEBUG1 - 17:09:17.571553 [2514/2514]: Removing /var/run/lttng/kconsumerd/error (in sessiond_cleanup() at main.c:621)
DEBUG1 - 17:09:17.572050 [2514/2514]: Removing directory /var/run/lttng/kconsumerd (in sessiond_cleanup() at main.c:627)
DEBUG1 - 17:09:17.572713 [2514/2514]: Removing /var/run/lttng/ustconsumerd32/error (in sessiond_cleanup() at main.c:634)
DEBUG1 - 17:09:17.573205 [2514/2514]: Removing directory /var/run/lttng/ustconsumerd32 (in sessiond_cleanup() at main.c:640)
DEBUG1 - 17:09:17.573692 [2514/2514]: Removing /var/run/lttng/ustconsumerd64/error (in sessiond_cleanup() at main.c:647)
DEBUG1 - 17:09:17.574750 [2514/2514]: Removing directory /var/run/lttng/ustconsumerd64 (in sessiond_cleanup() at main.c:653)
DEBUG1 - 17:09:17.575264 [2514/2514]: Cleaning up all sessions (in sessiond_cleanup() at main.c:656)
DEBUG1 - 17:09:17.575528 [2514/2514]: Tearing down kernel session (in kernel_destroy_session() at kernel.c:894)
DEBUG1 - 17:09:17.575792 [2514/2514]: [trace] Closing session fd 31 (in trace_kernel_destroy_session() at trace-kernel.c:546)
DEBUG1 - 17:09:17.576048 [2514/2514]: [trace] Closing metadata stream fd 41 (in trace_kernel_destroy_session() at trace-kernel.c:556)
DEBUG1 - 17:09:17.576328 [2514/2514]: [trace] Closing metadata fd 40 (in trace_kernel_destroy_metadata() at trace-kernel.c:519)
DEBUG1 - 17:09:17.576712 [2514/2514]: [trace] Closing channel fd 36 (in trace_kernel_destroy_channel() at trace-kernel.c:481)
DEBUG1 - 17:09:17.577037 [2514/2514]: [trace] Closing stream fd 38 (in trace_kernel_destroy_stream() at trace-kernel.c:412)
DEBUG1 - 17:09:17.577350 [2514/2514]: [trace] Closing event fd 39 (in trace_kernel_destroy_event() at trace-kernel.c:438)
DEBUG1 - 17:09:17.577671 [2514/2514]: [trace] Closing event fd 37 (in trace_kernel_destroy_event() at trace-kernel.c:438)
DEBUG1 - 17:09:17.601129 [2514/2514]: Destroying session my-session (in session_destroy() at session.c:331)
DEBUG1 - 17:09:17.601488 [2514/2514]: Empty ltt_sessions_ht_by_id, destroying it (in del_session_ht() at session.c:240)
DEBUG1 - 17:09:17.604762 [2514/2514]: Waiting for complete teardown of consumerd (PID: 2531) (in wait_consumer() at main.c:563)
DEBUG1 - 17:09:17.646042 [2514/2514]: Cleaning up all agent apps (in sessiond_cleanup() at main.c:673)
DEBUG1 - 17:09:17.646383 [2514/2514]: Closing all UST sockets (in sessiond_cleanup() at main.c:676)
DEBUG1 - 17:09:17.646827 [2514/2514]: Unloading kernel modules (in sessiond_cleanup() at main.c:688)
DEBUG1 - 17:09:17.679630 [2514/2514]: Modprobe removal successful lttng-probe-workqueue (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.685021 [2514/2514]: Modprobe removal successful lttng-probe-vmscan (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.694569 [2514/2514]: Modprobe removal successful lttng-probe-udp (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.704675 [2514/2514]: Modprobe removal successful lttng-probe-timer (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.710217 [2514/2514]: Modprobe removal successful lttng-probe-sunrpc (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.714817 [2514/2514]: Modprobe removal successful lttng-probe-statedump (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.723002 [2514/2514]: Modprobe removal successful lttng-probe-sock (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.735409 [2514/2514]: Modprobe removal successful lttng-probe-skb (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.744057 [2514/2514]: Modprobe removal successful lttng-probe-signal (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.759989 [2514/2514]: Modprobe removal successful lttng-probe-scsi (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.765414 [2514/2514]: Modprobe removal successful lttng-probe-sched (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.776514 [2514/2514]: Modprobe removal successful lttng-probe-regulator (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.779641 [2514/2514]: Modprobe removal successful lttng-probe-regmap (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.785603 [2514/2514]: Modprobe removal successful lttng-probe-rcu (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.795997 [2514/2514]: Modprobe removal successful lttng-probe-random (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.799947 [2514/2514]: Modprobe removal successful lttng-probe-printk (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.805431 [2514/2514]: Modprobe removal successful lttng-probe-power (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.815264 [2514/2514]: Modprobe removal successful lttng-probe-net (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.820624 [2514/2514]: Modprobe removal successful lttng-probe-napi (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.827674 [2514/2514]: Modprobe removal successful lttng-probe-module (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.836054 [2514/2514]: Modprobe removal successful lttng-probe-kmem (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.840195 [2514/2514]: Modprobe removal successful lttng-probe-jbd2 (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.845523 [2514/2514]: Modprobe removal successful lttng-probe-irq (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.856358 [2514/2514]: Modprobe removal successful lttng-probe-i2c (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.859613 [2514/2514]: Modprobe removal successful lttng-probe-gpio (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.865642 [2514/2514]: Modprobe removal successful lttng-probe-ext4 (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.876027 [2514/2514]: Modprobe removal successful lttng-probe-compaction (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:17.976780 [2514/2514]: Modprobe removal successful lttng-probe-block (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:18.905614 [2514/2514]: Modprobe removal successful lttng-ring-buffer-metadata-mmap-client (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:18.169410 [2514/2514]: Modprobe removal successful lttng-ring-buffer-client-mmap-overwrite (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:18.257106 [2514/2514]: Modprobe removal successful lttng-ring-buffer-client-mmap-discard (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:18.361706 [2514/2514]: Modprobe removal successful lttng-ring-buffer-metadata-client (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:18.395996 [2514/2514]: Modprobe removal successful lttng-ring-buffer-client-overwrite (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:18.455974 [2514/2514]: Modprobe removal successful lttng-ring-buffer-client-discard (in modprobe_remove_lttng() at modprobe.c:293)
DEBUG1 - 17:09:18.624923 [2514/2516]: [ht-cleanup] quit. (in thread_ht_cleanup() at ht-cleanup.c:206)
DEBUG1 - 17:09:18.629319 [2514/2516]: [ht-cleanup] Thread terminates. (in thread_ht_cleanup() at ht-cleanup.c:217)
DEBUG1 - 17:09:18.638259 [2514/2514]: Cleaning up options (in sessiond_cleanup_options() at main.c:735)
DEBUG1 - 17:09:18.643064 [2514/2514]: Destroying run_as worker (in run_as_destroy_worker() at runas.c:710)
DEBUG1 - 17:09:18.645707 [2514/2514]: Closing run_as worker socket (in run_as_destroy_worker() at runas.c:716)
DEBUG1 - 17:09:18.653732 [2515/2515]: run_as worker exiting (ret = 0) (in run_as_create_worker() at runas.c:660)
DEBUG1 - 17:09:18.983146 [2514/2514]: lttng-runas terminated with status code 0 (in run_as_destroy_worker() at runas.c:738)
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 4000 bytes
Desc: S/MIME Cryptographic Signature
URL: <https://lists.lttng.org/pipermail/lttng-dev/attachments/20170612/3cde95ee/attachment-0001.bin>
More information about the lttng-dev
mailing list