[lttng-dev] Odd behaviour of lttng 2.0 kernel event listing

[Thibault, Daniel]

> You have the exact same output as mine.
>
> 51 events is correct and the return data size is 41224. We'll have to add debug
> output. Let's check the event name returned by the kernel and those we send
> back. Please add this to the git head of lttng-tools:
>
> +++ b/src/bin/lttng-sessiond/kernel.c
> @@ -593,6 +593,8 @@ ssize_t kernel_list_events(int tracer_fd, struct lttng_event
**events)
>                elist[count].enabled = -1;
>                DBG3("Kernel event received '%s' and '%s' added to list", event, elist[count].name);
>                count++;
>
> Send back the results and from there we'll see if the event names returned by
> lttng-modules are correct.

   Since the initial session is the same as before, I've trimmed what follows down to the new bits (I've saved the full log to file, just in case):

$ sudo lttng -v list -k
Spawning a session daemon
DEBUG3: Creating LTTng run directory: /var/run/lttng [in create_lttng_rundir() at main.c:4087]
[...]
DEBUG2: Kernel consumer err path: /var/run/lttng/kconsumerd/error [in main() at main.c:4312]
DEBUG2: Kernel consumer cmd path: /var/run/lttng/kconsumerd/command [in main() at main.c:4314]
DEBUG1: Client socket path /var/run/lttng/client-lttng-sessiond [in main() at main.c:4357]
DEBUG1: Application socket path /var/run/lttng/apps-lttng-sessiond [in main() at main.c:4358]
DEBUG1: LTTng run directory path: /var/run/lttng [in main() at main.c:4359]
DEBUG2: UST consumer 32 bits err path: /var/run/lttng/ustconsumerd32/error [in main() at main.c:4368]
DEBUG2: UST consumer 32 bits cmd path: /var/run/lttng/ustconsumerd32/command [in main() at main.c:4370]
DEBUG2: UST consumer 64 bits err path: /var/run/lttng/ustconsumerd64/error [in main() at main.c:4379]
DEBUG2: UST consumer 64 bits cmd path: /var/run/lttng/ustconsumerd64/command [in main() at main.c:4381]
DEBUG2: Creating consumer directory: /var/run/lttng/kconsumerd [in set_consumer_sockets() at main.c:4129]
DEBUG1: Got debugfs path : /sys/kernel/debug [in init_kernel_tracer() at main.c:1790]
DEBUG1: Modprobe successfully lttng-ftrace [in modprobe_kernel_modules() at main.c:1732]
[...]
DEBUG1: [thread] Manage client started [in thread_manage_clients() at main.c:3629]
DEBUG1: SIGCHLD catched [in sighandler() at lttng.c:179]
DEBUG1: Getting kernel tracing events [in list_kernel_events() at commands/list.c:277]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3661]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3691]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3726]
DEBUG1: Processing client command 14 [in process_client_msg() at main.c:3212]
DEBUG3: Kernel event received 'sched_kthread_stop' and 'sched_kthread_stop' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'sched_kthread_stop_ret' and 'sched_kthread_stop_ret' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'sched_wakeup' and 'sched_wakeup' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'sched_wakeup_new' and 'sched_wakeup_new' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'sched_switch' and 'sched_switch' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'sched_migrate_task' and 'sched_migrate_task' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'sched_process_free' and 'sched_process_free' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'sched_process_exit' and 'sched_process_exit' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'sched_wait_task' and 'sched_wait_task' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'sched_process_wait' and 'sched_process_wait' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'sched_process_fork' and 'sched_process_fork' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'sched_stat_wait' and 'sched_stat_wait' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'sched_stat_sleep' and 'sched_stat_sleep' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'sched_stat_iowait' and 'sched_stat_iowait' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'sched_stat_runtime' and 'sched_stat_runtime' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'sched_pi_setprio' and 'sched_pi_setprio' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'kvm_userspace_exit' and 'kvm_userspace_exit' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'kvm_set_irq' and 'kvm_set_irq' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'kvm_ioapic_set_irq' and 'kvm_ioapic_set_irq' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'kvm_msi_set_irq' and 'kvm_msi_set_irq' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'kvm_ack_irq' and 'kvm_ack_irq' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'kvm_mmio' and 'kvm_mmio' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'kvm_fpu' and 'kvm_fpu' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'kvm_age_page' and 'kvm_age_page' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'kvm_try_async_get_page' and 'kvm_try_async_get_page' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'kvm_async_pf_doublefault' and 'kvm_async_pf_doublefault' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'kvm_async_pf_not_present' and 'kvm_async_pf_not_present' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'kvm_async_pf_ready' and 'kvm_async_pf_ready' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'kvm_async_pf_completed' and 'kvm_async_pf_completed' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'irq_handler_entry' and 'irq_handler_entry' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'irq_handler_exit' and 'irq_handler_exit' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'softirq_entry' and 'softirq_entry' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'softirq_exit' and 'softirq_exit' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'softirq_raise' and 'softirq_raise' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_rq_abort' and 'block_rq_abort' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_rq_requeue' and 'block_rq_requeue' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_rq_complete' and 'block_rq_complete' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_rq_insert' and 'block_rq_insert' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_rq_issue' and 'block_rq_issue' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_bio_bounce' and 'block_bio_bounce' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_bio_complete' and 'block_bio_complete' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_bio_backmerge' and 'block_bio_backmerge' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_bio_frontmerge' and 'block_bio_frontmerge' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_bio_queue' and 'block_bio_queue' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_getrq' and 'block_getrq' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_sleeprq' and 'block_sleeprq' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_plug' and 'block_plug' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_unplug' and 'block_unplug' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_split' and 'block_split' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_bio_remap' and 'block_bio_remap' added to list [in kernel_list_events() at kernel.c:596]
DEBUG3: Kernel event received 'block_rq_remap' and 'block_rq_remap' added to list [in kernel_list_events() at kernel.c:596]
DEBUG1: Kernel list events done (51 events) [in kernel_list_events() at kernel.c:601]
DEBUG1: Sending response (size: 41224, retcode: Success) [in thread_manage_clients() at main.c:3760]
Kernel events:
-------------
      sched_kthread_stop (type: tracepoint)
      [...]
      kvm_msi_set_irq (type: tracepoint)
       (type: tracepoint) [disabled]
      [...]
       (type: tracepoint) [disabled]

DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:492]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3661]


   As you can see, lttng-sessiond.kernel.kernel_list_events() copies the event correctly to elist[]. The strings must disappear further down the line.

Daniel U. Thibault
R & D pour la défense Canada - Valcartier (RDDC Valcartier) / Defence R&D Canada - Valcartier (DRDC Valcartier)
Système de systèmes (SdS) / System of Systems (SoS)
Solutions informatiques et expérimentations (SIE) / Computing Solutions and Experimentations (CSE)
2459 Boul. Pie XI Nord
Québec, QC  G3J 1X5
CANADA
Vox : (418) 844-4000 x4245
Fax : (418) 844-4538
NAC: 918V QSDJ
Gouvernement du Canada / Government of Canada
<http://www.valcartier.drdc-rddc.gc.ca/>