Project

General

Profile

Bug #607

lttng snapshot record fails for --buffers-pid traces

Added by Daniel U. Thibault over 6 years ago. Updated over 6 years ago.

Status:
Invalid
Priority:
Normal
Assignee:
-
Target version:
Start date:
07/29/2013
Due date:
% Done:

0%

Estimated time:

Description

Using (very nearly all up to date):
lttng-modules-2.3.0-rc1-1-5420784
lttng-tools-2.3.0-rc2-6-81ea21b
lttng-ust-2.3.0-rc1-2-92414a6
userspace-rcu-0.7.4-204-(0.7.7-63)-a5bae03

As a member of the tracing group:

$ lttng create snaps --snapshot
Session snaps created.
Default snapshot output set to: /home/daniel/lttng-traces/snaps-20130729-143544
Snapshot mode set. Every channel enabled for that session will be set in overwrite mode and mmap output.
$ lttng enable-channel ch0 --buffers-pid -u
UST channel ch0 enabled for session snaps
$ lttng enable-event -a -c ch0 -u
All UST events are enabled in channel ch0
$ lttng start
Tracing started for session snaps
$ /usr/src/lttng-ust-2.3.0-rc1/doc/examples/easy-ust/sample
sample starting
sample done
$ lttng snapshot record
Snapshot recorded successfully for session snaps

If the above is run with --buffers-uid instead of --buffers-pid, the snapshot is generated just fine. But with --buffers-pid, I get no output at all on disc.

Here is a (partial) log of lttng-sessiond:

DEBUG1 [14057/14158]: Sending response (size: 16, retcode: Success) (in thread_manage_clients() at main.c:3765)
DEBUG1 [14057/14158]: Clean command context structure (in clean_command_ctx() at main.c:538)
DEBUG1 [14057/14158]: Accepting client command ... (in thread_manage_clients() at main.c:3629)
DEBUG1 [14057/14158]: Wait for client response (in thread_manage_clients() at main.c:3671)
DEBUG1 [14057/14158]: Receiving data from client ... (in thread_manage_clients() at main.c:3716)
DEBUG1 [14057/14158]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:3720)
DEBUG1 [14057/14158]: Clean command context structure (in clean_command_ctx() at main.c:538)
DEBUG1 [14057/14158]: Accepting client command ... (in thread_manage_clients() at main.c:3629)
DEBUG1 [14057/14158]: Wait for client response (in thread_manage_clients() at main.c:3671)
DEBUG1 [14057/14158]: Receiving data from client ... (in thread_manage_clients() at main.c:3716)
DEBUG1 [14057/14158]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:3720)
DEBUG1 [14057/14158]: Clean command context structure (in clean_command_ctx() at main.c:538)
DEBUG1 [14057/14158]: Accepting client command ... (in thread_manage_clients() at main.c:3629)
DEBUG1 [14057/14158]: Wait for client response (in thread_manage_clients() at main.c:3671)
DEBUG1 [14057/14158]: Receiving data from client ... (in thread_manage_clients() at main.c:3716)
DEBUG1 [14057/14158]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:3720)
DEBUG1 [14057/14158]: Clean command context structure (in clean_command_ctx() at main.c:538)
DEBUG1 [14057/14158]: Accepting client command ... (in thread_manage_clients() at main.c:3629)
DEBUG1 [14057/14158]: Wait for client response (in thread_manage_clients() at main.c:3671)
DEBUG1 [14057/14158]: Receiving data from client ... (in thread_manage_clients() at main.c:3716)
DEBUG1 [14057/14158]: Processing client command 6 (in process_client_msg() at main.c:2544)
DEBUG1 [14057/14158]: Getting session snaps by name (in process_client_msg() at main.c:2621)
DEBUG2 [14057/14158]: Trying to find session by name snaps (in session_find_by_name() at session.c:133)
DEBUG3 [14057/14158]: Consumer socket created (fd: 30) and added to output (in consumer_create_socket() at consumer.c:232)
DEBUG1 [14057/14158]: Setting relayd for session snaps (in cmd_setup_relayd() at cmd.c:668)
DEBUG2 [14057/14158]: Trace UST channel ch0 found by name (in trace_ust_find_channel_by_name() at trace-ust.c:144)
DEBUG2 [14057/14158]: Trace UST event * NOT found (in trace_ust_find_event() at trace-ust.c:183)
DEBUG2 [14057/14158]: Trace UST event *, loglevel (0,-1) created (in trace_ust_create_event() at trace-ust.c:372)
DEBUG1 [14057/14158]: UST app creating event * for all apps for session id 0 (in ust_app_create_event_glb() at ust-app.c:3597)
DEBUG1 [14057/14158]: Event UST * created in channel ch0 (in event_ust_enable_tracepoint() at event.c:467)
DEBUG1 [14057/14158]: Sending response (size: 16, retcode: Success) (in thread_manage_clients() at main.c:3765)
DEBUG1 [14057/14158]: Clean command context structure (in clean_command_ctx() at main.c:538)
DEBUG1 [14057/14158]: Accepting client command ... (in thread_manage_clients() at main.c:3629)
DEBUG1 [14057/14158]: Wait for client response (in thread_manage_clients() at main.c:3671)
DEBUG1 [14057/14158]: Receiving data from client ... (in thread_manage_clients() at main.c:3716)
DEBUG1 [14057/14158]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:3720)
DEBUG1 [14057/14158]: Clean command context structure (in clean_command_ctx() at main.c:538)
DEBUG1 [14057/14158]: Accepting client command ... (in thread_manage_clients() at main.c:3629)
DEBUG1 [14057/14158]: Wait for client response (in thread_manage_clients() at main.c:3671)
DEBUG1 [14057/14158]: Receiving data from client ... (in thread_manage_clients() at main.c:3716)
DEBUG1 [14057/14158]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:3720)
DEBUG1 [14057/14158]: Clean command context structure (in clean_command_ctx() at main.c:538)
DEBUG1 [14057/14158]: Accepting client command ... (in thread_manage_clients() at main.c:3629)
DEBUG1 [14057/14158]: Wait for client response (in thread_manage_clients() at main.c:3671)
DEBUG1 [14057/14158]: Receiving data from client ... (in thread_manage_clients() at main.c:3716)
DEBUG1 [14057/14158]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:3720)
DEBUG1 [14057/14158]: Clean command context structure (in clean_command_ctx() at main.c:538)
DEBUG1 [14057/14158]: Accepting client command ... (in thread_manage_clients() at main.c:3629)
DEBUG1 [14057/14158]: Wait for client response (in thread_manage_clients() at main.c:3671)
DEBUG1 [14057/14158]: Receiving data from client ... (in thread_manage_clients() at main.c:3716)
DEBUG1 [14057/14158]: Processing client command 16 (in process_client_msg() at main.c:2544)
DEBUG1 [14057/14158]: Getting session snaps by name (in process_client_msg() at main.c:2621)
DEBUG2 [14057/14158]: Trying to find session by name snaps (in session_find_by_name() at session.c:133)
DEBUG1 [14057/14158]: Starting all UST traces (in ust_app_start_trace_all() at ust-app.c:3927)
DEBUG1 [14057/14158]: Sending response (size: 16, retcode: Success) (in thread_manage_clients() at main.c:3765)
DEBUG1 [14057/14158]: Clean command context structure (in clean_command_ctx() at main.c:538)
DEBUG1 [14057/14158]: Accepting client command ... (in thread_manage_clients() at main.c:3629)
DEBUG1 [14057/14160]: UST registration received with pid:14177 ppid:2703 uid:1000 gid:1000 sock:27 name:sample_static (version 5.0) (in thread_registration_apps() at main.c:1843)
DEBUG1 [14057/14160]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:104)
DEBUG1 [14057/14160]: Accepting application registration (in thread_registration_apps() at main.c:1747)
DEBUG1 [14057/14159]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:90)
DEBUG1 [14057/14159]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:75)
DEBUG1 [14057/14159]: Dispatching UST registration pid:14177 ppid:2703 uid:1000 gid:1000 sock:27 name:sample_static (version 5.0) (in thread_dispatch_ust_registration() at main.c:1532)
DEBUG3 [14057/14159]: UST app creating application for socket 27 (in ust_app_create() at ust-app.c:2708)
DEBUG3 [14057/14159]: Created hashtable size 4 at 0x801680 of type 2 (in lttng_ht_new() at hashtable.c:112)
DEBUG3 [14057/14159]: Created hashtable size 4 at 0x801a40 of type 1 (in lttng_ht_new() at hashtable.c:112)
DEBUG1 [14057/14159]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1520)
DEBUG1 [14057/14160]: UST registration received with pid:14177 ppid:2703 uid:1000 gid:1000 sock:32 name:sample_static (version 5.0) (in thread_registration_apps() at main.c:1843)
DEBUG1 [14057/14160]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:104)
DEBUG1 [14057/14160]: Accepting application registration (in thread_registration_apps() at main.c:1747)
DEBUG1 [14057/14159]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:90)
DEBUG1 [14057/14159]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:75)
DEBUG1 [14057/14159]: Dispatching UST registration pid:14177 ppid:2703 uid:1000 gid:1000 sock:32 name:sample_static (version 5.0) (in thread_dispatch_ust_registration() at main.c:1532)
DEBUG3 [14057/14159]: UST app notify socket 32 is set (in thread_dispatch_ust_registration() at main.c:1589)
DEBUG1 [14057/14159]: App registered with pid:14177 ppid:2703 uid:1000 gid:1000 sock:27 name:sample_static notify_sock:32 (version 5.0) (in ust_app_add() at ust-app.c:2796)
DEBUG2 [14057/14159]: UST app global update for app sock 27 for session id 0 (in ust_app_global_update() at ust-app.c:4066)
DEBUG2 [14057/14159]: UST app pid: 14177 session id 0 not found, creating it (in create_ust_app_session() at ust-app.c:1688)
DEBUG3 [14057/14159]: Created hashtable size 4 at 0x802eb0 of type 0 (in lttng_ht_new() at hashtable.c:112)
DEBUG2 [14057/14159]: Shadow copy of session handle -1 (in shadow_copy_session() at ust-app.c:1447)
DEBUG2 [14057/14159]: Channel ch0 not found on shadow session copy, creating it (in shadow_copy_session() at ust-app.c:1494)
DEBUG3 [14057/14159]: Created hashtable size 4 at 0x803f80 of type 1 (in lttng_ht_new() at hashtable.c:112)
DEBUG3 [14057/14159]: Created hashtable size 4 at 0x804220 of type 0 (in lttng_ht_new() at hashtable.c:112)
DEBUG3 [14057/14159]: UST app channel ch0 allocated (in alloc_ust_app_channel() at ust-app.c:842)
DEBUG2 [14057/14159]: UST app shadow copy of channel ch0 started (in shadow_copy_channel() at ust-app.c:1375)
DEBUG2 [14057/14159]: UST event * not found on shadow copy channel (in shadow_copy_channel() at ust-app.c:1414)
DEBUG3 [14057/14159]: UST app event * allocated (in alloc_ust_app_event() at ust-app.c:898)
DEBUG3 [14057/14159]: UST app shadow copy of channel ch0 done (in shadow_copy_channel() at ust-app.c:1424)
DEBUG3 [14057/14159]: Buffer registry per PID find id: 1 (in buffer_reg_pid_find() at buffer-registry.c:301)
DEBUG3 [14057/14159]: Created hashtable size 4 at 0x804970 of type 2 (in lttng_ht_new() at hashtable.c:112)
DEBUG3 [14057/14159]: Buffer registry per PID created with session id: 1 (in buffer_reg_pid_create() at buffer-registry.c:262)
DEBUG3 [14057/14159]: Buffer registry per PID adding to global registry with id: 1 (in buffer_reg_pid_add() at buffer-registry.c:281)
DEBUG3 [14057/14159]: Created hashtable size 4 at 0x804dd0 of type 2 (in lttng_ht_new() at hashtable.c:112)
DEBUG3 [14057/14159]: 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 = "ffba45ba-7cf2-48e2-b168-049915f762c6";
    byte_order = le;
    packet.header := struct {
        uint32_t magic;
        uint8_t  uuid[16];
        uint32_t stream_id;
    };
};

" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [14057/14159]: Append to metadata: "env {
    hostname = "sds-dut-vb";
    domain = "ust";
    tracer_name = "lttng-ust";
    tracer_major = 2;
    tracer_minor = 3;
" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [14057/14159]: Append to metadata: "    tracer_patchlevel = 0;
    vpid = 14177;
    procname = "sample_static";
" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [14057/14159]: Append to metadata: "};

" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [14057/14159]: Append to metadata: "clock {
    name = monotonic;
" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [14057/14159]: Append to metadata: "    uuid = "de0d3d7c-156f-400f-a4e0-f6d1df71dc05";
" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [14057/14159]: Append to metadata: "    description = "Monotonic Clock";
    freq = 1000000000; /* Frequency, in Hz */
    /* clock value offset from Epoch is: offset * (1/freq) */
    offset = 1374771059118680254;
};

" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [14057/14159]: 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:144)
DEBUG3 [14057/14159]: 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;
    unsigned long events_discarded;
    uint32_t cpu_id;
};

" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [14057/14159]: 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:144)
DEBUG3 [14057/14159]: UST app buffer registry per PID created successfully (in setup_buffer_reg_pid() at ust-app.c:1592)
DEBUG3 [14057/14162]: UST thread notify added sock 32 to pollset (in ust_thread_manage_notify() at ust-thread.c:131)
DEBUG3 [14057/14162]: [ust-thread] Manage notify polling on 3 fds (in ust_thread_manage_notify() at ust-thread.c:61)
DEBUG2 [14057/14159]: UST app session created successfully with handle 1 (in create_ust_app_session() at ust-app.c:1749)
DEBUG1 [14057/14159]: UST app creating channel ch0 with per PID buffers (in create_channel_per_pid() at ust-app.c:2350)
DEBUG3 [14057/14159]: Buffer registry per PID find id: 1 (in buffer_reg_pid_find() at buffer-registry.c:301)
DEBUG3 [14057/14159]: Created hashtable size 4 at 0x805210 of type 0 (in lttng_ht_new() at hashtable.c:112)
DEBUG2 [14057/14159]: Asking UST consumer for channel (in ask_channel_creation() at ust-consumer.c:118)
DEBUG3 [14057/14159]: UST registry channel finding key 1 (in ust_registry_channel_find() at ust-registry.c:425)
DEBUG2 [14057/14159]: UST ask channel 1 successfully done with 1 stream(s) (in ask_channel_creation() at ust-consumer.c:186)
DEBUG2 [14057/14159]: UST app stream 1 received succesfully (in ust_consumer_get_channel() at ust-consumer.c:303)
DEBUG3 [14057/14159]: UST app consumer has no more stream available (in ust_consumer_get_channel() at ust-consumer.c:286)
DEBUG1 [14057/14159]: UST app sending channel ch0 to UST app sock 27 (in send_channel_pid_to_ust() at ust-app.c:1244)
DEBUG2 [14057/14159]: UST app send channel to sock 27 pid 14177 (name: ch0, key: 0) (in ust_consumer_send_channel_to_ust() at ust-consumer.c:407)
DEBUG2 [14057/14159]: UST consumer send stream to app 27 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:372)
DEBUG2 [14057/14159]: UST app event * created successfully for pid:14177 (in create_ust_event() at ust-app.c:1301)
DEBUG1 [14057/14159]: Starting tracing for ust app pid 14177 (in ust_app_start_trace() at ust-app.c:3652)
DEBUG3 [14057/14159]: Buffer registry per PID find id: 1 (in buffer_reg_pid_find() at buffer-registry.c:301)
DEBUG3 [14057/14159]: Created hashtable size 4 at 0x806fd0 of type 1 (in lttng_ht_new() at hashtable.c:112)
DEBUG3 [14057/14159]: Created hashtable size 4 at 0x807270 of type 0 (in lttng_ht_new() at hashtable.c:112)
DEBUG3 [14057/14159]: UST app channel metadata allocated (in alloc_ust_app_channel() at ust-app.c:842)
DEBUG2 [14057/14159]: Asking UST consumer for channel (in ask_channel_creation() at ust-consumer.c:118)
DEBUG2 [14057/14159]: UST ask channel 2 successfully done with 0 stream(s) (in ask_channel_creation() at ust-consumer.c:186)
DEBUG2 [14057/14159]: Consumer setup metadata channel key 2 (in consumer_setup_metadata() at consumer.c:1141)
DEBUG2 [14057/14159]: UST metadata with key 2 created for app pid 14177 (in create_ust_app_metadata() at ust-app.c:2652)
DEBUG3 [14057/14159]: UST app deleting channel metadata (in delete_ust_app_channel() at ust-app.c:357)
DEBUG3 [14057/14159]: Buffer registry per PID find id: 1 (in buffer_reg_pid_find() at buffer-registry.c:301)
DEBUG3 [14057/14159]: UST registry channel finding key 2 (in ust_registry_channel_find() at ust-registry.c:425)
DEBUG3 [14057/14156]: [ht-thread] Polling on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:58)
DEBUG3 [14057/14156]: [ht-thread] Polling on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:58)
DEBUG3 [14057/14162]: UST app receiving notify from sock 32 (in ust_app_recv_notify() at ust-app.c:4699)
DEBUG2 [14057/14162]: UST app ustctl register channel received (in ust_app_recv_notify() at ust-app.c:4752)
DEBUG3 [14057/14162]: Buffer registry per PID find id: 1 (in buffer_reg_pid_find() at buffer-registry.c:301)
DEBUG3 [14057/14162]: UST registry channel finding key 1 (in ust_registry_channel_find() at ust-registry.c:425)
DEBUG3 [14057/14162]: 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:144)
DEBUG3 [14057/14162]: Append to metadata: "};

" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [14057/14162]: UST app replying to register channel key 1 with id 0, type: 1, ret: 0 (in reply_ust_register_channel() at ust-app.c:4566)
DEBUG3 [14057/14162]: [ust-thread] Manage notify polling on 3 fds (in ust_thread_manage_notify() at ust-thread.c:61)
DEBUG2 [14057/14159]: UST trace started for app pid 14177 (in ust_app_global_update() at ust-app.c:4154)
DEBUG1 [14057/14159]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1520)
DEBUG1 [14057/14161]: Apps with sock 27 added to poll set (in thread_manage_apps() at main.c:1307)
DEBUG1 [14057/14161]: Apps thread polling on 3 fds (in thread_manage_apps() at main.c:1238)
DEBUG3 [14057/14162]: UST app receiving notify from sock 32 (in ust_app_recv_notify() at ust-app.c:4699)
DEBUG2 [14057/14162]: UST app ustctl register event received (in ust_app_recv_notify() at ust-app.c:4719)
DEBUG3 [14057/14162]: Buffer registry per PID find id: 1 (in buffer_reg_pid_find() at buffer-registry.c:301)
DEBUG3 [14057/14162]: UST registry channel finding key 1 (in ust_registry_channel_find() at ust-registry.c:425)
DEBUG3 [14057/14162]: UST registry creating event with event: sample_component:event, sig: char *, text, id: 0, chan_objd: 2, sess_objd: 1, chan_id: 0 (in ust_registry_create_event() at ust-registry.c:234)
DEBUG3 [14057/14162]: Append to metadata: "event {
    name = "sample_component:event";
    id = 0;
    stream_id = 0;
" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [14057/14162]: Append to metadata: "    loglevel = 4;
" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [14057/14162]: Append to metadata: "    fields := struct {
" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [14057/14162]: Append to metadata: "        string _message;
" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [14057/14162]: Append to metadata: "    };
};

" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [14057/14162]: UST registry event sample_component:event with id 0 added successfully (in add_event_ust_registry() at ust-app.c:4680)
DEBUG3 [14057/14162]: [ust-thread] Manage notify polling on 3 fds (in ust_thread_manage_notify() at ust-thread.c:61)
DEBUG1 [14057/14161]: PID 14177 unregistering with sock 27 (in ust_app_unregister() at ust-app.c:2847)
DEBUG3 [14057/14161]: Buffer registry per PID find id: 1 (in buffer_reg_pid_find() at buffer-registry.c:301)
DEBUG2 [14057/14161]: Consumer push metadata to consumer socket 30 (in consumer_push_metadata() at consumer.c:1175)
DEBUG3 [14057/14161]: Consumer pushing metadata on sock 30 of len 2489 (in consumer_push_metadata() at consumer.c:1188)
DEBUG2 [14057/14161]: Consumer close metadata channel key 2 (in consumer_close_metadata() at consumer.c:1108)
DEBUG1 [14057/14161]: Apps thread polling on 2 fds (in thread_manage_apps() at main.c:1238)
DEBUG1 [14057/14162]: UST app notify socket unregister 32 (in ust_app_notify_sock_unregister() at ust-app.c:4826)
DEBUG2 [14057/14162]: UST app find by notify sock 32 not found (in find_app_by_notify_sock() at ust-app.c:988)
DEBUG3 [14057/14162]: [ust-thread] Manage notify polling on 2 fds (in ust_thread_manage_notify() at ust-thread.c:61)
DEBUG3 [14057/14180]: Call RCU deleting app PID 14177 (in delete_ust_app_rcu() at ust-app.c:742)
DEBUG3 [14057/14180]: Buffer registry per PID find id: 1 (in buffer_reg_pid_find() at buffer-registry.c:301)
DEBUG3 [14057/14180]: UST app deleting channel ch0 (in delete_ust_app_channel() at ust-app.c:357)
DEBUG3 [14057/14180]: Buffer registry per PID find id: 1 (in buffer_reg_pid_find() at buffer-registry.c:301)
DEBUG3 [14057/14180]: UST registry channel finding key 1 (in ust_registry_channel_find() at ust-registry.c:425)
DEBUG3 [14057/14180]: Buffer registry per PID find id: 1 (in buffer_reg_pid_find() at buffer-registry.c:301)
DEBUG3 [14057/14180]: Buffer registry per PID destroy with id: 1 (in buffer_reg_pid_destroy() at buffer-registry.c:686)
DEBUG3 [14057/14156]: [ht-thread] Polling on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:58)
DEBUG3 [14057/14156]: [ht-thread] Polling on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:58)
DEBUG2 [14057/14180]: UST app pid 14177 deleted (in delete_ust_app() at ust-app.c:727)
DEBUG3 [14057/14156]: [ht-thread] Polling on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:58)
DEBUG3 [14057/14156]: [ht-thread] Polling on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:58)
DEBUG3 [14057/14156]: [ht-thread] Polling on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:58)
DEBUG3 [14057/14180]: Buffer registry session destroy (in buffer_reg_session_destroy() at buffer-registry.c:543)
DEBUG3 [14057/14156]: [ht-thread] Polling on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:58)
DEBUG3 [14057/14156]: [ht-thread] Polling on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:58)
DEBUG3 [14057/14156]: [ht-thread] Polling on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:58)
DEBUG1 [14057/14158]: Wait for client response (in thread_manage_clients() at main.c:3671)
DEBUG1 [14057/14158]: Receiving data from client ... (in thread_manage_clients() at main.c:3716)
DEBUG1 [14057/14158]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:3720)
DEBUG1 [14057/14158]: Clean command context structure (in clean_command_ctx() at main.c:538)
DEBUG1 [14057/14158]: Accepting client command ... (in thread_manage_clients() at main.c:3629)
DEBUG1 [14057/14158]: Wait for client response (in thread_manage_clients() at main.c:3671)
DEBUG1 [14057/14158]: Receiving data from client ... (in thread_manage_clients() at main.c:3716)
DEBUG1 [14057/14158]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:3720)
DEBUG1 [14057/14158]: Clean command context structure (in clean_command_ctx() at main.c:538)
DEBUG1 [14057/14158]: Accepting client command ... (in thread_manage_clients() at main.c:3629)
DEBUG1 [14057/14158]: Wait for client response (in thread_manage_clients() at main.c:3671)
DEBUG1 [14057/14158]: Receiving data from client ... (in thread_manage_clients() at main.c:3716)
DEBUG1 [14057/14158]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:3720)
DEBUG1 [14057/14158]: Clean command context structure (in clean_command_ctx() at main.c:538)
DEBUG1 [14057/14158]: Accepting client command ... (in thread_manage_clients() at main.c:3629)
DEBUG1 [14057/14158]: Wait for client response (in thread_manage_clients() at main.c:3671)
DEBUG1 [14057/14158]: Receiving data from client ... (in thread_manage_clients() at main.c:3716)
DEBUG1 [14057/14158]: Processing client command 28 (in process_client_msg() at main.c:2544)
DEBUG1 [14057/14158]: Getting session snaps by name (in process_client_msg() at main.c:2621)
DEBUG2 [14057/14158]: Trying to find session by name snaps (in session_find_by_name() at session.c:133)
DEBUG1 [14057/14158]: Cmd snapshot record for session snaps (in cmd_snapshot_record() at cmd.c:2706)
DEBUG2 [14057/14158]: Set relayd object from snapshot output (in set_relayd_for_snapshot() at cmd.c:2526)
DEBUG1 [14057/14158]: Sending response (size: 16, retcode: Success) (in thread_manage_clients() at main.c:3765)
DEBUG1 [14057/14158]: Clean command context structure (in clean_command_ctx() at main.c:538)
DEBUG1 [14057/14158]: Accepting client command ... (in thread_manage_clients() at main.c:3629)

Files

sessiond.log (61.3 KB) sessiond.log Session and consumer daemon log Daniel U. Thibault, 09/04/2013 05:05 PM
#1

Updated by David Goulet over 6 years ago

  • Project changed from LTTng to LTTng-tools
#2

Updated by David Goulet over 6 years ago

  • Status changed from New to Won't fix

Can not reproduce with upstrea master.

I will close this one with invalid since it seems fixed on my side. If you can reproduce it, we'll reopen it and make sure to attach session daemon logs.

Thanks!

#3

Updated by David Goulet over 6 years ago

  • Status changed from Won't fix to Invalid
#4

Updated by Daniel U. Thibault over 6 years ago

Alas, I can still reproduce this using:

lttng-modules-2.3.0-rc2-7 c126f57
lttng-tools-2.3.0-rc3-1 3e618c7
lttng-ust-2.3.0-rc2-1 07d2f70
userspace-rcu-0.7.4-210-(0.7.7-69) e53ab1e

Ubuntu 12.04LTS 3.20-40-virtual, freshly rebooted

Same sequence of instructions as before:

$ lttng create snapsfind --snapshot
Session snapsfind created.
Default snapshot output set to: /home/daniel/lttng-traces/snapsfind-20130904-165608
Snapshot mode set. Every channel enabled for that session will be set in overwrite mode and mmap output.
$ lttng enable-channel ch0 --buffers-pid -u
UST channel ch0 enabled for session snapsfind
$ lttng enable-event -a -c ch0 -u
All UST events are enabled in channel ch0
$ lttng start
Tracing started for session snapsfind
$ /usr/src/lttng-ust-2.3.0-rc2/doc/examples/easy-ust/sample
sample starting
sample done
$ lttng snapshot record
Snapshot recorded successfully for session snapsfind
$ lttng destroy
Session snapsfind destroyed

The session and consumer daemon log was captured using:

$ sudo lttng-sessiond -vvv -ZZZ 1 &> /home/daniel/lttng-traces/sessiond.log

(The '1' argument for '-ZZZ' is due to bug 588)

#5

Updated by Daniel U. Thibault over 6 years ago

Finally figured this one out. It's a feature, not a bug. When tracing per-process ID, the buffers are evanescent, so you get a trace on disc only if you trigger the record action while the process is active. If the process has come and gone, so has its trace.

Also available in: Atom PDF