[lttng-dev] core seen in relayd_cleanup()
Aravind HT
aravind.ht at gmail.com
Mon Dec 12 09:09:34 UTC 2016
Hi,
Providing the complete info as it was outstanding from my side, took some
time to reproduce this with logs.
This happens when the system is trying to shutdown, apps that are tracing
along with lttng_* processes get a SIGTERM. In this specific scenario, an
app called trace_server and lttng_relayd are being terminated with SIGTERM
almost at the same time. There are a couple of active tracing sessions at
this point.
I have cut out only those logs which are relevant to this issue from the
time the app ( trace_server ) registers with sessiond and have added
comments inline below.
Couldnt attach the complete logs due to mailing size limits.
*####### SESSIOND : App Registration ########*
DEBUG1 - 03:25:04.481119 [20477/20484]: UST registration received with
pid:19671 ppid:1 uid:0 gid:0 sock:81 name:trace_server (version 6.1) (in
thread_registration_apps() at main.c:2306)
DEBUG1 - 03:25:04.481122 [20477/20484]: Futex n to 1 wake done (in
futex_nto1_wake() at futex.c:123)
DEBUG1 - 03:25:04.481124 [20477/20484]: Accepting application registration
(in thread_registration_apps() at main.c:2192)
DEBUG1 - 03:25:04.494180 [20477/20483]: Dispatching UST registration
pid:19671 ppid:1 uid:0 gid:0 sock:81 name:trace_server (version 6.1) (in
thread_dispatch_ust_registration() at main.c:1950)
DEBUG3 - 03:25:04.494184 [20477/20483]: UST app creating application for
socket 81 (in ust_app_create() at ust-app.c:3294)
DEBUG3 - 03:25:04.494186 [20477/20483]: Created hashtable size 4 at
0x7f66fc01f790 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 03:25:04.494189 [20477/20483]: Created hashtable size 4 at
0x7f66fc01fbd0 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 03:25:04.494194 [20477/20483]: Created hashtable size 4 at
0x7f66fc020010 of type 1 (in lttng_ht_new() at hashtable.c:14
DEBUG1 - 03:25:04.498652 [20477/20484]: UST registration received with
pid:19671 ppid:1 uid:0 gid:0 sock:173 name:trace_server (version 6.1) (in
thread_registration_apps() at main.c:2306)
DEBUG1 - 03:25:04.498655 [20477/20484]: Futex n to 1 wake done (in
futex_nto1_wake() at futex.c:123)
DEBUG1 - 03:25:04.498656 [20477/20484]: Accepting application registration
(in thread_registration_apps() at main.c:2192)
DEBUG1 - 03:25:04.524781 [20477/20483]: Dispatching UST registration
pid:19671 ppid:1 uid:0 gid:0 sock:173 name:trace_server (version 6.1) (in
thread_dispatch_ust_registration() at main.c:1950)
DEBUG3 - 03:25:04.524784 [20477/20483]: UST app notify socket 173 is set
(in thread_dispatch_ust_registration() at main.c:2007)
DEBUG1 - 03:25:04.524788 [20477/20483]: App registered with pid:19671
ppid:1 uid:0 gid:0 sock:81 name:trace_server notify_sock:173 (version 6.1)
(in ust_app_add() at ust-app.c:3383)
DEBUG2 - 03:25:07.156727 [20477/20482]: UST app pid: 19671 session id 0 not
found, creating it (in create_ust_app_session() at ust-app.c:2171)
DEBUG3 - 03:25:07.156733 [20477/20482]: Created hashtable size 4 at
0x7f67040e5420 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG2 - 03:25:07.156742 [20477/20482]: Shadow copy of session handle -1
(in shadow_copy_session() at ust-app.c:1869)
DEBUG3 - 03:25:07.156749 [20477/20482]: Buffer registry per PID find id: 19
(in buffer_reg_pid_find() at buffer-registry.c:317)
DEBUG3 - 03:25:07.156761 [20477/20482]: Created hashtable size 4 at
0x7f67040e7810 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 03:25:07.156763 [20477/20482]: Buffer registry per PID created
with session id: 19 (in buffer_reg_pid_create() at buffer-registry.c:278)
DEBUG3 - 03:25:07.156775 [20477/20482]: Created hashtable size 4 at
0x7f67040ead00 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 03:25:07.156778 [20477/20482]: Created hashtable size 4 at
0x7f67040eb140 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 03:25:07.156814 [20477/20482]: Append to metadata: "/* CTF 1.8 */
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 03:25:07.156825 [20477/20482]: 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;
...
...
...
#### REMOVED METADATA PRINTS HERE #####
...
...
DEBUG3 - 03:25:07.156953 [20477/20482]: Buffer registry per PID adding to
global registry with id: 19 (in buffer_reg_pid_add() at
buffer-registry.c:297)
DEBUG3 - 03:25:07.156956 [20477/20482]: UST app buffer registry per PID
created successfully (in setup_buffer_reg_pid() at ust-app.c:2065)
DEBUG2 - 03:25:07.157171 [20477/20482]: UST app session created
successfully with handle 1 (in create_ust_app_session() at ust-app.c:2246)
DEBUG3 - 03:25:07.157178 [20477/20482]: Created hashtable size 4 at
0x7f67040eb7a0 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 03:25:07.157181 [20477/20482]: Created hashtable size 4 at
0x7f67040ebbe0 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 03:25:07.157183 [20477/20482]: UST app channel DefaultChannel
allocated (in alloc_ust_app_channel() at ust-app.c:1051)
DEBUG2 - 03:25:07.157185 [20477/20482]: UST app shadow copy of channel
DefaultChannel started (in shadow_copy_channel() at ust-app.c:1794)
DEBUG3 - 03:25:07.157188 [20477/20482]: UST app shadow copy of channel
DefaultChannel done (in shadow_copy_channel() at ust-app.c:1845)
DEBUG1 - 03:25:07.157190 [20477/20482]: UST app creating channel
DefaultChannel with per PID buffers (in create_channel_per_pid() at
ust-app.c:2946)
DEBUG3 - 03:25:07.157192 [20477/20482]: Buffer registry per PID find id: 19
(in buffer_reg_pid_find() at buffer-registry.c:317)
DEBUG3 - 03:25:07.157196 [20477/20482]: Created hashtable size 4 at
0x7f67040ec0a0 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG2 - 03:25:07.157204 [20477/20482]: Asking UST consumer for channel (in
ask_channel_creation() at ust-consumer.c:120)
DEBUG3 - 03:25:07.157212 [20477/20482]: UST registry channel finding key 19
(in ust_registry_channel_find() at ust-registry.c:784)
DEBUG2 - 03:25:07.165001 [20477/20482]: UST ask channel 19 successfully
done with 2 stream(s) (in ask_channel_creation() at ust-consumer.c:215)
DEBUG2 - 03:25:07.165714 [20477/20482]: UST app stream 1 received
successfully (in ust_consumer_get_channel() at ust-consumer.c:330)
DEBUG2 - 03:25:07.165757 [20477/20482]: UST app stream 2 received
successfully (in ust_consumer_get_channel() at ust-consumer.c:330)
DEBUG3 - 03:25:07.165767 [20477/20482]: UST app consumer has no more stream
available (in ust_consumer_get_channel() at ust-consumer.c:313)
DEBUG1 - 03:25:07.165773 [20477/20482]: UST app sending channel
DefaultChannel to UST app sock 81 (in send_channel_pid_to_ust() at
ust-app.c:1623)
DEBUG2 - 03:25:07.165775 [20477/20482]: UST app send channel to sock 81 pid
19671 (name: DefaultChannel, key: 0) (in ust_consumer_send_channel_to_ust()
at ust-consumer.c:436)
DEBUG2 - 03:25:07.166019 [20477/20482]: UST consumer send stream to app 81
(in ust_consumer_send_stream_to_ust() at ust-consumer.c:399)
DEBUG2 - 03:25:07.166057 [20477/20482]: UST consumer send stream to app 81
(in ust_consumer_send_stream_to_ust() at ust-consumer.c:399)
DEBUG2 - 03:25:07.166086 [20477/20482]: UST app create channel
DefaultChannel for PID 19671 completed (in create_ust_app_channel() at
ust-app.c:3086)
*######## CONSUMERD : creating
channels
############*
* ######## KEY 104 and 106 are nothing but
wait fd's, referred to as streams 37 and 38 below on the RELAYD side.
############*
DEBUG1 - 03:25:07.157239 [20706/20713]:
Incoming command on sock (in consumer_thread_sessiond_poll() at
consumer.c:3182)
DEBUG1 - 03:25:07.157258 [20706/20713]:
Allocated channel (key 19) (in consumer_allocate_channel() at
consumer.c:1024)
DEBUG3 - 03:25:07.157262 [20706/20713]:
Creating channel to ustctl with attr: [overwrite: 0, subbuf_size: 1048576,
num_subbuf: 4, switch_timer_interval: 0, read_timer_interval: 0, output: 0,
type: 0 (in create_ust_channel() at ust-consumer.c:458)
DEBUG3 - 03:25:07.164838 [20706/20713]:
Allocated stream DefaultChannel_0 (key 104, chan_key 19 relayd_id 2,
session_id 0 (in consumer_allocate_stream() at consumer.c:608)
DEBUG1 - 03:25:07.164852 [20706/20713]: UST
consumer add stream DefaultChannel_0 (key: 104) with relayd id 0 (in
create_ust_streams() at ust-consumer.c:347)
DEBUG3 - 03:25:07.164855 [20706/20713]:
Allocated stream DefaultChannel_1 (key 106, chan_key 19 relayd_id 2,
session_id 0 (in consumer_allocate_stream() at consumer.c:608)
DEBUG1 - 03:25:07.164857 [20706/20713]: UST
consumer add stream DefaultChannel_1 (key: 106) with relayd id 0 (in
create_ust_streams() at ust-consumer.c:347)
DEBUG1 - 03:25:07.164911 [20706/20713]: UST
consumer channel added (key: 19) (in add_channel() at ust-consumer.c:115)
DEBUG1 - 03:25:07.164927 [20706/20713]:
received command on sock (in consumer_thread_sessiond_poll() at
consumer.c:3198)
DEBUG1 - 03:25:07.165055 [20706/20713]:
Incoming command on sock (in consumer_thread_sessiond_poll() at
consumer.c:3182)
DEBUG1 - 03:25:07.165071 [20706/20713]: UST
consumer sending channel DefaultChannel to sessiond (in
send_sessiond_channel() at ust-consumer.c:562)
DEBUG1 - 03:25:07.165076 [20706/20713]:
Relayd adding stream for channel name DefaultChannel_0 (in
relayd_add_stream() at relayd.c:252)
DEBUG3 - 03:25:07.165148 [20706/20713]:
Relayd sending command 1 of size 4400 (in send_command() at relayd.c:81)
DEBUG3 - 03:25:07.165152 [20706/20713]:
Relayd waiting for reply of size 12 (in recv_reply() at relayd.c:101)
DEBUG1 - 03:25:07.165510 [20706/20713]:
Relayd stream added successfully with handle 37 (in relayd_add_stream() at
relayd.c:317)
DEBUG1 - 03:25:07.165513 [20706/20713]:
Stream DefaultChannel_0 with key 104 sent to relayd id 2 (in
consumer_send_relayd_stream() at consumer.c:811)
DEBUG1 - 03:25:07.165516 [20706/20713]:
Relayd adding stream for channel name DefaultChannel_1 (in
relayd_add_stream() at relayd.c:252)
DEBUG3 - 03:25:07.165532 [20706/20713]:
Relayd sending command 1 of size 4400 (in send_command() at relayd.c:81)
DEBUG3 - 03:25:07.165535 [20706/20713]:
Relayd waiting for reply of size 12 (in recv_reply() at relayd.c:101)
DEBUG1 - 03:25:07.165618 [20706/20713]:
Relayd stream added successfully with handle 38 (in relayd_add_stream() at
relayd.c:317)
DEBUG1 - 03:25:07.165621 [20706/20713]:
Stream DefaultChannel_1 with key 106 sent to relayd id 2 (in
consumer_send_relayd_stream() at consumer.c:811)
DEBUG1 - 03:25:07.165636 [20706/20713]: UST
consumer sending stream 104 to sessiond (in send_sessiond_stream() at
ust-consumer.c:533)
DEBUG1 - 03:25:07.165643 [20706/20713]: UST
consumer sending stream 106 to sessiond (in send_sessiond_stream() at
ust-consumer.c:533)
DEBUG1 - 03:25:07.165663 [20706/20713]: UST
consumer NULL stream sent to sessiond (in send_sessiond_channel() at
ust-consumer.c:626)
DEBUG3 - 03:25:07.165665 [20706/20713]:
Adding consumer stream 104 (in consumer_add_data_stream() at consumer.c:634)
DEBUG3 - 03:25:07.165682 [20706/20713]:
Adding consumer stream 106 (in consumer_add_data_stream() at consumer.c:634)
DEBUG1 - 03:25:07.165688 [20706/20713]:
received command on sock (in consumer_thread_sessiond_poll() at
consumer.c:3198)
*#######
RELAYD : logs for creation of streams 37 and 38 #######*
DEBUG3 -
03:25:09.165076 [19663/19666]: Receiving data of size 84 for stream id 37
seqnum 0 (in relay_process_data() at main.c:2289)
DEBUG1 -
03:25:09.165079 [19663/19666]: handle_index_data: stream 37 net_seq_num 0
data offset 0 (in handle_index_data() at main.c:2178)
DEBUG3 -
03:25:09.165081 [19663/19666]: Finding index for stream id 37 and seq_num 0
(in relay_index_get_by_id_or_create() at index.c:133)
DEBUG2 -
03:25:09.165084 [19663/19666]: Creating relay index for stream id 37 and
seqnum 0 (in relay_index_create() at index.c:44)
DEBUG2 -
03:25:09.165087 [19663/19666]: Adding relay index with stream id 37 and
seqnum 0 (in relay_index_add_unique() at index.c:81)
DEBUG2 -
03:25:09.165090 [19663/19666]: Index found or created in HT for stream ID
37 and seqnum 0 (in relay_index_get_by_id_or_create() at index.c:165)
DEBUG1 -
03:25:09.165203 [19663/19666]: utils_unlink_stream_file
/var/log/lttng-traces/evo-xb49-re0//DefaultSession-20161207-032506//ust/pid/
trace_server-19671-20161207-032507/index/DefaultChannel_0_0.idx returns -1
(in utils_unlink_stream_file() at utils.c:830)
DEBUG2 -
03:25:09.165267 [19663/19666]: Relay wrote 84 bytes to tracefile for stream
id 37 (in relay_process_data() at main.c:2360)
DEBUG1 -
03:25:09.165278 [19663/19666]: stream put for stream id 37 (in stream_put()
at stream.c:335)
DEBUG1 -
03:25:09.165280 [19663/19666]: stream put stream id 37 refcount 3 (in
stream_put() at stream.c:352)
DEBUG3 -
03:25:09.167450 [19663/19666]: Receiving data of size 84 for stream id 38
seqnum 0 (in relay_process_data() at main.c:2289)
DEBUG1 -
03:25:09.167481 [19663/19666]: handle_index_data: stream 38 net_seq_num 0
data offset 0 (in handle_index_data() at main.c:2178)
DEBUG3 -
03:25:09.167484 [19663/19666]: Finding index for stream id 38 and seq_num 0
(in relay_index_get_by_id_or_create() at index.c:133)
DEBUG2 -
03:25:09.167486 [19663/19666]: Creating relay index for stream id 38 and
seqnum 0 (in relay_index_create() at index.c:44)
DEBUG2 -
03:25:09.167488 [19663/19666]: Adding relay index with stream id 38 and
seqnum 0 (in relay_index_add_unique() at index.c:81)
DEBUG2 -
03:25:09.167490 [19663/19666]: Index found or created in HT for stream ID
38 and seqnum 0 (in relay_index_get_by_id_or_create() at index.c:165)
DEBUG1 -
03:25:09.167507 [19663/19666]: utils_unlink_stream_file
/var/log/lttng-traces/evo-xb49-re0//DefaultSession-20161207-032506//ust/pid/
trace_server-19671-20161207-032507/index/DefaultChannel_1_0.idx returns -1
(in utils_unlink_stream_file() at utils.c:830)
DEBUG2 -
03:25:09.167561 [19663/19666]: Relay wrote 84 bytes to tracefile for stream
id 38 (in relay_process_data() at main.c:2360)
DEBUG1 -
03:25:09.167571 [19663/19666]: stream put for stream id 38 (in stream_put()
at stream.c:335)
DEBUG1 -
03:25:09.167573 [19663/19666]: stream put stream id 38 refcount 3 (in
stream_put() at stream.c:352)
*######### SESSIOND: Start tracing ###########*
*######### Metadata key or channel 92 here is NOT and FD, just another
number ##########*
DEBUG1 - 03:25:07.923556 [20477/20482]: Starting tracing for ust app pid
19671 (in ust_app_start_trace() at ust-app.c:4318)
DEBUG3 - 03:25:07.923560 [20477/20482]: Buffer registry per PID find id: 19
(in buffer_reg_pid_find() at buffer-registry.c:317)
DEBUG3 - 03:25:07.923565 [20477/20482]: Created hashtable size 4 at
0x7f67040a8070 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 03:25:07.923581 [20477/20482]: Created hashtable size 4 at
0x7f67040a84b0 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 03:25:07.923584 [20477/20482]: UST app channel metadata allocated
(in alloc_ust_app_channel() at ust-app.c:1051)
DEBUG2 - 03:25:07.923587 [20477/20482]: Asking UST consumer for channel (in
ask_channel_creation() at ust-consumer.c:120)
DEBUG2 - 03:25:07.923704 [20477/20482]: UST ask channel 92 successfully
done with 1 stream(s) (in ask_channel_creation() at ust-consumer.c:215)
DEBUG2 - 03:25:07.923708 [20477/20482]: Consumer setup metadata channel key
92 (in consumer_setup_metadata() at consumer.c:1273)
DEBUG2 - 03:25:07.924027 [20477/20482]: UST metadata with key 92 created
for app pid 19671 (in create_ust_app_metadata() at ust-app.c:3245)
DEBUG3 - 03:25:07.924031 [20477/20482]: UST app deleting channel metadata
(in delete_ust_app_channel() at ust-app.c:457)
DEBUG3 - 03:25:07.924033 [20477/20482]: Buffer registry per PID find id: 19
(in buffer_reg_pid_find() at buffer-registry.c:317)
DEBUG3 - 03:25:07.924036 [20477/20482]: UST registry channel finding key 92
(in ust_registry_channel_find() at ust-registry.c:784)
*######### CONSUMERD : adding metadata channel
####################*
* ########## 378 is the FD for this channel
####################*
DEBUG1 - 03:25:07.923604 [20706/20713]:
Incoming command on sock (in consumer_thread_sessiond_poll() at
consumer.c:3182)
DEBUG1 - 03:25:07.923623 [20706/20713]:
Allocated channel (key 92) (in consumer_allocate_channel() at
consumer.c:1024)
DEBUG3 - 03:25:07.923626 [20706/20713]:
Creating channel to ustctl with attr: [overwrite: 0, subbuf_size: 4096,
num_subbuf: 2, switch_timer_interval: 0, read_timer_interval: 0, output: 0,
type: 1 (in create_ust_channel() at ust-consumer.c:458)
DEBUG3 - 03:25:07.923683 [20706/20713]:
Allocated stream metadata (key 378, chan_key 92 relayd_id 2, session_id 0
(in consumer_allocate_stream() at consumer.c:608)
DEBUG1 - 03:25:07.923687 [20706/20713]: UST
consumer add stream metadata (key: 378) with relayd id 0 (in
create_ust_streams() at ust-consumer.c:347)
DEBUG1 - 03:25:07.923690 [20706/20713]:
Allocated metadata cache of 4096 bytes (in consumer_metadata_cache_allocate()
at consumer-metadata-cache.c:198)
DEBUG1 - 03:25:07.923694 [20706/20713]: UST
consumer channel added (key: 92) (in add_channel() at ust-consumer.c:115)
DEBUG1 - 03:25:07.923697 [20706/20713]:
received command on sock (in consumer_thread_sessiond_poll() at
consumer.c:3198)
DEBUG1 - 03:25:07.923721 [20706/20713]:
Incoming command on sock (in consumer_thread_sessiond_poll() at
consumer.c:3182)
DEBUG1 - 03:25:07.923731 [20706/20713]: UST
consumer setup metadata key 92 (in setup_metadata() at ust-consumer.c:876)
DEBUG1 - 03:25:07.923734 [20706/20713]:
Relayd adding stream for channel name metadata (in relayd_add_stream() at
relayd.c:252)
DEBUG3 - 03:25:07.923759 [20706/20713]:
Relayd sending command 1 of size 4400 (in send_command() at relayd.c:81)
DEBUG3 - 03:25:07.923762 [20706/20713]:
Relayd waiting for reply of size 12 (in recv_reply() at relayd.c:101)
DEBUG1 - 03:25:07.923884 [20706/20713]:
Relayd stream added successfully with handle 165 (in relayd_add_stream() at
relayd.c:317)
DEBUG1 - 03:25:07.923888 [20706/20713]:
Stream metadata with key 378 sent to relayd id 2 (in
consumer_send_relayd_stream() at consumer.c:811)
DEBUG1 - 03:25:07.923890 [20706/20713]:
Relayd sending streams sent. (in relayd_streams_sent() at relayd.c:336)
DEBUG3 - 03:25:07.923903 [20706/20713]:
Relayd sending command 16 of size 24 (in send_command() at relayd.c:81)
DEBUG3 - 03:25:07.923906 [20706/20713]:
Relayd waiting for reply of size 4 (in recv_reply() at relayd.c:101)
DEBUG1 - 03:25:07.923947 [20706/20713]:
Relayd streams sent success (in relayd_streams_sent() at relayd.c:369)
DEBUG1 - 03:25:07.923950 [20706/20713]: All
streams sent relayd id 2 (in consumer_send_relayd_streams_sent() at
consumer.c:849)
DEBUG3 - 03:25:07.923952 [20706/20713]:
Adding metadata stream 378 to hash table (in consumer_add_metadata_stream()
at consumer.c:2115)
*##############
RELAYD : adding metadata channel handle id 165 #######################*
DEBUG3 -
03:25:07.918301 [19663/19666]: Relayd worker thread polling... (in
relay_thread_worker() at main.c:2481)
DEBUG3 -
03:25:07.923820 [19663/19666]: Created hashtable size 4 at 0x7f1d4404ceb0
of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG1 -
03:25:07.923855 [19663/19666]: Tracefile /var/log/lttng-traces/evo-
xb49-re0//DefaultSession-20161207-032506//ust/pid/
trace_server-19671-20161207-032507/metadata created (in stream_create() at
stream.c:151)
DEBUG1 -
03:25:07.923859 [19663/19666]: Relay new stream added metadata with ID 165
(in stream_create() at stream.c:177)
*####### SESSIOND : closing for trace_server #######*
DEBUG1 - 03:39:11.176955 [20477/20482]: Flushing session buffers for all
ust apps (in ust_app_flush_session() at ust-app.c:4583)
.....
*###### app going down at this point is picked up by sessiond ######*
DEBUG1 - 03:55:51.236181 [20477/20485]: PID 19671 unregistering with sock
81 (in ust_app_unregister() at ust-app.c:3437)
DEBUG1 - 03:55:51.236190 [20477/20485]: Flushing app session buffers for
ust app pid 19671 (in ust_app_flush_app_session() at ust-app.c:4522)
DEBUG2 - 03:55:51.236196 [20477/20485]: Consumer flush channel key 383 (in
consumer_flush_channel() at consumer.c:1174)
DEBUG3 - 03:55:51.236791 [20477/20485]: Buffer registry per PID find id:
201 (in buffer_reg_pid_find() at buffer-registry.c:317)
DEBUG3 - 03:55:51.236798 [20477/20485]: No metadata to push for metadata
key 456 (in ust_app_push_metadata() at ust-app.c:587)
DEBUG2 - 03:55:51.236802 [20477/20485]: Consumer close metadata channel key
456 (in consumer_close_metadata() at consumer.c:1240)
DEBUG1 - 03:55:51.237113 [20477/20485]: Flushing app session buffers for
ust app pid 19671 (in ust_app_flush_app_session() at ust-app.c:4522)
DEBUG2 - 03:55:51.237120 [20477/20485]: Consumer flush channel key 19 (in
consumer_flush_channel() at consumer.c:1174)
DEBUG3 - 03:55:51.237386 [20477/20485]: Buffer registry per PID find id: 19
(in buffer_reg_pid_find() at buffer-registry.c:317)
DEBUG3 - 03:55:51.237391 [20477/20485]: No metadata to push for metadata
key 92 (in ust_app_push_metadata() at ust-app.c:587)
DEBUG2 - 03:55:51.237393 [20477/20485]: Consumer close metadata channel key
92 (in consumer_close_metadata() at consumer.c:1240)
*###### CONSUMERD : getting request to
close ###########*
DEBUG1 - 03:55:51.237169 [20706/20713]:
Incoming command on sock (in consumer_thread_sessiond_poll() at
consumer.c:3182)
DEBUG1 - 03:55:51.237179 [20706/20713]: UST
consumer flush channel key 19 (in flush_channel() at ust-consumer.c:751)
DEBUG1 - 03:55:51.237362 [20706/20713]:
received command on sock (in consumer_thread_sessiond_poll() at
consumer.c:3198)
DEBUG1 - 03:55:51.237411 [20706/20713]:
Incoming command on sock (in consumer_thread_sessiond_poll() at
consumer.c:3182)
DEBUG1 - 03:55:51.237420 [20706/20713]: UST
consumer close metadata key 92 (in close_metadata() at ust-consumer.c:835)
DEBUG1 - 03:55:51.277601 [20706/20713]:
Closing metadata channel key 92 (in lttng_ustconsumer_close_metadata() at
ust-consumer.c:2720)
DEBUG1 - 03:55:51.277619 [20706/20713]:
received command on sock (in consumer_thread_sessiond_poll() at
consumer.c:3198)
* ##### CONSUMERD : thread 20713 handling
close_metadata is done here , but 20711 got an event for fd 378 associated
with key 92 #####*
* ##### consumerd is also polling on 104 and
106, they have not hup|err here, there is a crucial delay ######*
DEBUG1 - 03:55:51.277662 [20706/20711]:
Metadata poll return from wait with 78 fd(s) (in
consumer_thread_metadata_poll() at consumer.c:2274)
DEBUG1 - 03:55:51.277664 [20706/20711]:
Metadata event caught in thread (in consumer_thread_metadata_poll() at
consumer.c:2276)
DEBUG1 - 03:55:51.277668 [20706/20711]:
Metadata fd 378 is hup|err. (in consumer_thread_metadata_poll() at
consumer.c:2390)
DEBUG1 - 03:55:51.277684 [20706/20711]:
Attempting to flush and consume the UST buffers (in
consumer_thread_metadata_poll() at consumer.c:2394)
DEBUG1 - 03:55:51.277701 [20706/20711]: In
UST read_subbuffer (wait_fd: 378, name: metadata) (in
lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2439)
DEBUG1 - 03:55:51.279107 [20706/20711]:
Relayd sending metadata of size 49 (in relayd_send_metadata() at
relayd.c:459)
.....
DEBUG3 - 03:55:51.279123 [20706/20711]:
Relayd sending command 6 of size 24 (in send_command() at relayd.c:81)
DEBUG2 - 03:55:51.279126 [20706/20711]:
Relayd metadata added successfully (in relayd_send_metadata() at
relayd.c:467)
DEBUG1 - 03:55:51.279130 [20706/20711]:
Metadata stream id 165 with padding 4059 written before data (in
write_relayd_metadata_id() at consumer.c:1483)
DEBUG1 - 03:55:51.279134 [20706/20711]:
Consumer mmap write() ret 37 (len 37) (in
lttng_consumer_on_read_subbuffer_mmap()
at consumer.c:1661)
DEBUG1 - 03:55:51.279140 [20706/20711]: In
UST read_subbuffer (wait_fd: 378, name: metadata) (in
lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2439)
DEBUG3 - 03:55:51.279146 [20706/20711]:
Consumer delete metadata stream 378 (in consumer_del_metadata_stream() at
consumer.c:2062)
DEBUG1 - 03:55:51.279157 [20706/20711]:
Closing metadata channel key 92 (in lttng_ustconsumer_close_metadata() at
ust-consumer.c:2720)
DEBUG1 - 03:55:51.279166 [20706/20711]:
Relayd closing stream id 165 (in relayd_send_close_stream() at relayd.c:594)
DEBUG3 - 03:55:51.279170 [20706/20711]:
Relayd sending command 7 of size 40 (in send_command() at relayd.c:81)
DEBUG3 - 03:55:51.279172 [20706/20711]:
Relayd waiting for reply of size 4 (in recv_reply() at relayd.c:101)
DEBUG3 - 03:55:51.289333 [20477/20490]:
Call RCU deleting app PID 19671 (in delete_ust_app_rcu() at ust-app.c:947)
DEBUG3 - 03:55:51.289540 [20477/20490]:
Buffer registry per PID find id: 19 (in buffer_reg_pid_find() at
buffer-registry.c:317)
DEBUG3 - 03:55:51.289551 [20477/20490]: UST
app deleting channel DefaultChannel (in delete_ust_app_channel() at
ust-app.c:457)
DEBUG3 - 03:55:51.289568 [20477/20490]:
Buffer registry per PID find id: 19 (in buffer_reg_pid_find() at
buffer-registry.c:317)
DEBUG3 - 03:55:51.289571 [20477/20490]: UST
registry channel finding key 19 (in ust_registry_channel_find() at
ust-registry.c:784)
DEBUG3 - 03:55:51.289613 [20477/20490]:
Session 0 found by id. (in session_find_by_id() at session.c:312)
DEBUG3 - 03:55:51.289616 [20477/20490]:
Consumer discarded events id 0 (in consumer_get_discarded_events() at
consumer.c:1428)
.....
DEBUG1 - 03:55:51.289658 [20706/20713]:
Incoming command on sock (in consumer_thread_sessiond_poll() at
consumer.c:3182)
DEBUG1 - 03:55:51.289700 [20706/20713]: UST
consumer discarded events command for session id 0 (in
lttng_ustconsumer_recv_cmd() at ust-consumer.c:1769)
DEBUG1 - 03:55:51.323528 [20706/20711]:
Relayd close stream id 165 successfully (in relayd_send_close_stream() at
relayd.c:623)
DEBUG1 - 03:55:51.323587 [20706/20711]:
Consumer delete channel key 92 (in consumer_del_channel() at consumer.c:359)
* #####
RELAYD : GOT SIGTERM and is going down, cleaning streams here #######*
* #####
RELAYD : trying to close streams 37 and 38. 37 got closed, 38 has data
pending !! #####################*
DEBUG1 -
03:55:51.653672 [19663/19666]: Trying to close stream 37 (in
try_stream_close() at stream.c:360)
DEBUG1 -
03:55:51.653675 [19663/19666]: stream_unpublish:: lttng_ht_del() : stream
0x7f1d440125b0 refcount 1 stream 37 trace 19 session 1 (in
stream_unpublish() at stream.c:252)
DEBUG1 -
03:55:51.653677 [19663/19666]: Succeeded in closing stream 37 (in
try_stream_close() at stream.c:431)
DEBUG1 -
03:55:51.653678 [19663/19666]: stream put for stream id 37 (in stream_put()
at stream.c:335)
DEBUG1 -
03:55:51.653680 [19663/19666]: stream put stream id 37 refcount 1 (in
stream_put() at stream.c:352)
DEBUG1 -
03:55:51.653681 [19663/19666]: Releasing stream id 37 (in stream_release()
at stream.c:305)
DEBUG1 -
03:55:51.653687 [19663/19666]: Trying to close stream 38 (in
try_stream_close() at stream.c:360)
DEBUG1 -
03:55:51.653690 [19663/19666]: closing stream 38 aborted since it still has
data pending (in try_stream_close() at stream.c:420)
* ####### CONSUMERD : errors on fd 104 and
106 detected. Relayd has completely exited at this point. ###########*
DEBUG1 - 03:55:51.850362 [20706/20712]: fd
104 is hup|err|nval. Attempting flush and read. (in
consumer_thread_data_poll() at consumer.c:2661)
DEBUG1 - 03:55:51.850371 [20706/20712]:
Polling fd 104 tells it has hung up. (in consumer_thread_data_poll() at
consumer.c:2672)
DEBUG1 - 03:55:51.850375 [20706/20712]: fd
106 is hup|err|nval. Attempting flush and read. (in
consumer_thread_data_poll() at consumer.c:2661)
DEBUG1 - 03:55:51.850377 [20706/20712]:
Polling fd 106 tells it has hung up. (in consumer_thread_data_poll() at
consumer.c:2672)
* ###### RELAYD has waited for the
"data_pending" to get completed for the stream 106 and gone down, now
consumerd realizes that the app is going down ######*
DEBUG1 - 03:55:51.859249 [20706/20712]:
Normal read on fd 104 (in consumer_thread_data_poll() at consumer.c:2636)
DEBUG1 - 03:55:51.859253 [20706/20712]: In
UST read_subbuffer (wait_fd: 104, name: DefaultChannel_0) (in
lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2439)
DEBUG1 - 03:55:51.859256 [20706/20712]:
Reserving sub buffer failed (everything is normal, it is due to
concurrency) [ret: -11] (in lttng_ustconsumer_read_subbuffer() at
ust-consumer.c:2490)
DEBUG1 - 03:55:51.859478 [20706/20712]:
Delete flag set to data stream 106 (in update_endpoint_status_by_netidx()
at consumer.c:446)
DEBUG1 - 03:55:51.859546 [20706/20712]:
Normal read on fd 106 (in consumer_thread_data_poll() at consumer.c:2636)
DEBUG1 - 03:55:51.859548 [20706/20712]: In
UST read_subbuffer (wait_fd: 106, name: DefaultChannel_1) (in
lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2439)
DEBUG1 - 03:55:51.859550 [20706/20712]:
Reserving sub buffer failed (everything is normal, it is due to
concurrency) [ret: -11] (in lttng_ustconsumer_read_subbuffer() at
ust-consumer.c:2490)
DEBUG1 - 03:55:51.859577 [20706/20712]:
Polling fd 104 tells it has hung up. (in consumer_thread_data_poll() at
consumer.c:2672)
DEBUG1 - 03:55:51.859582 [20706/20712]:
Consumer stream destroy monitored key: 104 (in destroy_close_stream() at
consumer-stream.c:268)
DEBUG1 - 03:55:51.859592 [20706/20712]:
Polling fd 106 tells it has hung up. (in consumer_thread_data_poll() at
consumer.c:2672)
DEBUG1 - 03:55:51.859596 [20706/20712]:
Consumer stream destroy monitored key: 106 (in destroy_close_stream() at
consumer-stream.c:268)
DEBUG1 - 03:55:51.859602 [20706/20712]:
Consumer delete channel key 19 (in consumer_del_channel() at consumer.c:359)
DEBUG1 - 03:55:51.868988 [20706/20711]:
Closing metadata channel key 104 (in lttng_ustconsumer_close_metadata() at
ust-consumer.c:2720)
DEBUG1 - 03:55:51.869001 [20706/20711]:
Consumer delete channel key 104 (in consumer_del_channel() at
consumer.c:359)
DEBUG1 - 03:55:51.869347 [20706/20711]:
Closing metadata channel key 106 (in lttng_ustconsumer_close_metadata() at
ust-consumer.c:2720)
DEBUG1 - 03:55:51.869359 [20706/20711]:
Consumer delete channel key 106 (in consumer_del_channel() at
consumer.c:359)
DEBUG1 - 03:55:52.179253 [20706/20713]:
Incoming command on sock (in consumer_thread_sessiond_poll() at
consumer.c:3182)
DEBUG1 - 03:55:52.179487 [20706/20713]: UST
consumer close metadata key 104 (in close_metadata() at ust-consumer.c:835)
DEBUG1 - 03:55:52.179517 [20706/20713]: UST
consumer close metadata 104 not found (in close_metadata() at
ust-consumer.c:845)
DEBUG1 - 03:55:52.229354 [20706/20713]:
Incoming command on sock (in consumer_thread_sessiond_poll() at
consumer.c:3182)
DEBUG1 - 03:55:52.229443 [20706/20713]: UST
consumer close metadata key 106 (in close_metadata() at ust-consumer.c:835)
DEBUG1 - 03:55:52.229469 [20706/20713]: UST
consumer close metadata 106 not found (in close_metadata() at
ust-consumer.c:845)
Regards,
Aravind.
On Wed, Nov 30, 2016 at 1:10 AM, Jérémie Galarneau <
jeremie.galarneau at efficios.com> wrote:
> On 29 November 2016 at 14:19, Aravind HT <aravind.ht at gmail.com> wrote:
> > Hi,
> >
> >
> > I was in the processes of upgrading to 2.8.1 and see the below relayd
> core.
> > I am trying to get the logs for this but is proving hard to reproduce
> this
> > scenario with full logs enabled and also as this is happening in a
> complex
> > environment, not sure why relayd is exiting.
> >
> > For the meantime, from https://lwn.net/Articles/573432/ , I see that
> > cds_lfht_destroy() may fail in case the ht is not empty. Should the
> assert()
> > be there in relayd_cleanup() or do you know what can cause/simulate this
> > crash ?
>
> Hi Aravind,
>
> The assert() is there because, at that point, the streams should have
> been "torn down" cleanly before exiting. It is a check to ensure we
> don't leak the object and, more importantly, properly close the trace
> on disk.
>
> I am not sure what can cause the stream to be "dangling" at this
> point. Are you killing the relay daemon or is it closing on its own
> (presumably after encountering an error)?.
>
> Thanks,
> Jérémie
>
> > Ive tried killing relayd with SIGINT, SIGTERM when sesions are being
> active
> > and that doesnt reproduce this.
> >
> > 55 ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
> > [Current thread is 1 (Thread 0x7fd7e7c0e980 (LWP 29366))]
> > (gdb) info threads
> > Id Target Id Frame
> > 2 Thread 0x7fd7e1b1c700 (LWP 29375) 0x00007fd7e6701996 in _int_free
> > (av=<optimized out>, p=<optimized out>, have_lock=0) at malloc.c:4059
> > * 1 Thread 0x7fd7e7c0e980 (LWP 29366) 0x00007fd7e66bd367 in __GI_raise
> > (sig=sig at entry=6) at ../sysdeps/unix/sysv/linux/raise.c:55
> > (gdb) bt full
> > #0 0x00007fd7e66bd367 in __GI_raise (sig=sig at entry=6) at
> > ../sysdeps/unix/sysv/linux/raise.c:55
> > resultvar = 0
> > pid = 29366
> > selftid = 29366
> > #1 0x00007fd7e66c033a in __GI_abort () at abort.c:89
> > save_stage = 2
> > act = {__sigaction_handler = {sa_handler = 0x4, sa_sigaction =
> 0x4},
> > sa_mask = {__val = {5, 48, 140732823353744, 3924933264, 0, 0, 0,
> > 21474836480, 140732823353896, 140565261773123,
> > 140732823353696, 140565261807824, 140565261789000,
> > 140732823354144, 140565282869248, 140565261789000}}, sa_flags = 4462201,
> > sa_restorer = 0x4416c0 <__PRETTY_FUNCTION__.5555>}
> > sigs = {__val = {32, 0 <repeats 15 times>}}
> > #2 0x00007fd7e66b644d in __assert_fail_base (fmt=0x7fd7e67f2748
> "%s%s%s:%u:
> > %s%sAssertion `%s' failed.\n%n", assertion=assertion at entry=0x441679
> "!ret",
> > file=file at entry=0x4415da "hashtable.c",
> > line=line at entry=162, function=function at entry=0x4416c0
> > <__PRETTY_FUNCTION__.5555> "lttng_ht_destroy") at assert.c:92
> > str = 0x65b310 ""
> > total = 4096
> > #3 0x00007fd7e66b6502 in __GI___assert_fail (assertion=0x441679 "!ret",
> > file=0x4415da "hashtable.c", line=162, function=0x4416c0
> > <__PRETTY_FUNCTION__.5555> "lttng_ht_destroy") at assert.c:101
> > No locals.
> > #4 0x0000000000422f17 in lttng_ht_destroy (ht=0x65a0e0) at
> hashtable.c:162
> > ret = -1
> > __PRETTY_FUNCTION__ = "lttng_ht_destroy"
> > #5 0x000000000040803b in relayd_cleanup () at main.c:497
> > __func__ = "relayd_cleanup"
> > #6 0x000000000040ec4c in main (argc=5, argv=0x7ffee9f1bd68) at
> main.c:2939
> > ret = 0
> > retval = 0
> > status = 0x0
> > __func__ = "main"
> >
> > (gdb) f 4
> > #4 0x0000000000422f17 in lttng_ht_destroy (ht=0x65a0e0) at
> hashtable.c:162
> > 162 hashtable.c: No such file or directory.
> > (gdb) p *ht->ht
> > $1 = {max_nr_buckets = 9223372036854775808, mm = 0x7fd7e6e50920
> > <cds_lfht_mm_order>,
> > flavor = 0x7fd7e77b6340 <rcu_flavor_memb>, count = -1024, resize_mutex =
> > {__data = {
> > __lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins
> = 0,
> > __elision = 0, __list = {__prev = 0x0, __next = 0x0}},
> > __size = '\000' <repeats 39 times>, __align = 0}, resize_attr = 0x0,
> > in_progress_resize = 0, in_progress_destroy = 1, resize_target = 2048,
> > resize_initiated = 0, flags = 3, min_alloc_buckets_order = 0,
> > min_nr_alloc_buckets = 1,
> > split_count = 0x65b170, .., bucket_at = 0x7fd7e6c4e080 <bucket_at>, {
> > tbl_order = {0x65b280, 0x65b2a0, 0x65b2c0, 0x7fd7c40008c0,
> > 0x7fd7c4000910,
> > 0x7fd7c40009a0, 0x7fd7c4000ab0, 0x7fd7c4001070, 0x7fd7c4001480,
> > 0x7fd7c4001c90,
> > 0x7fd7c4003350, 0x7fd7c4005360, 0x0 <repeats 52 times>}, tbl_chunk
> =
> > 0x65af60,
> > tbl_mmap = 0x65b280}}
> >
> >
> > Regards,
> > Aravind.
> >
> > _______________________________________________
> > lttng-dev mailing list
> > lttng-dev at lists.lttng.org
> > https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
> >
>
>
>
> --
> Jérémie Galarneau
> EfficiOS Inc.
> http://www.efficios.com
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.lttng.org/pipermail/lttng-dev/attachments/20161212/22d96cd8/attachment-0001.html>
More information about the lttng-dev
mailing list