Project

General

Profile

Actions

Bug #607

closed

lttng snapshot record fails for --buffers-pid traces

Added by Daniel U. Thibault over 10 years ago. Updated over 10 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
Actions #1

Updated by David Goulet over 10 years ago

  • Project changed from LTTng to LTTng-tools
Actions #2

Updated by David Goulet over 10 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!

Actions #3

Updated by David Goulet over 10 years ago

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

Updated by Daniel U. Thibault over 10 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)

Actions #5

Updated by Daniel U. Thibault over 10 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.

Actions

Also available in: Atom PDF