2016-08-23 22:27:24 +08:00
|
|
|
/* AF_RXRPC tracepoints
|
|
|
|
|
*
|
|
|
|
|
* Copyright (C) 2016 Red Hat, Inc. All Rights Reserved.
|
|
|
|
|
* Written by David Howells (dhowells@redhat.com)
|
|
|
|
|
*
|
|
|
|
|
* This program is free software; you can redistribute it and/or
|
|
|
|
|
* modify it under the terms of the GNU General Public Licence
|
|
|
|
|
* as published by the Free Software Foundation; either version
|
|
|
|
|
* 2 of the Licence, or (at your option) any later version.
|
|
|
|
|
*/
|
|
|
|
|
#undef TRACE_SYSTEM
|
|
|
|
|
#define TRACE_SYSTEM rxrpc
|
|
|
|
|
|
|
|
|
|
#if !defined(_TRACE_RXRPC_H) || defined(TRACE_HEADER_MULTI_READ)
|
|
|
|
|
#define _TRACE_RXRPC_H
|
|
|
|
|
|
|
|
|
|
#include <linux/tracepoint.h>
|
2018-05-11 06:26:01 +08:00
|
|
|
#include <linux/errqueue.h>
|
2016-08-23 22:27:24 +08:00
|
|
|
|
2017-01-05 18:38:33 +08:00
|
|
|
/*
|
|
|
|
|
* Define enums for tracing information.
|
|
|
|
|
*
|
|
|
|
|
* These should all be kept sorted, making it easier to match the string
|
|
|
|
|
* mapping tables further on.
|
|
|
|
|
*/
|
|
|
|
|
#ifndef __RXRPC_DECLARE_TRACE_ENUMS_ONCE_ONLY
|
|
|
|
|
#define __RXRPC_DECLARE_TRACE_ENUMS_ONCE_ONLY
|
|
|
|
|
|
|
|
|
|
enum rxrpc_skb_trace {
|
|
|
|
|
rxrpc_skb_rx_cleaned,
|
|
|
|
|
rxrpc_skb_rx_freed,
|
|
|
|
|
rxrpc_skb_rx_got,
|
|
|
|
|
rxrpc_skb_rx_lost,
|
|
|
|
|
rxrpc_skb_rx_purged,
|
|
|
|
|
rxrpc_skb_rx_received,
|
|
|
|
|
rxrpc_skb_rx_rotated,
|
|
|
|
|
rxrpc_skb_rx_seen,
|
|
|
|
|
rxrpc_skb_tx_cleaned,
|
|
|
|
|
rxrpc_skb_tx_freed,
|
|
|
|
|
rxrpc_skb_tx_got,
|
|
|
|
|
rxrpc_skb_tx_new,
|
|
|
|
|
rxrpc_skb_tx_rotated,
|
|
|
|
|
rxrpc_skb_tx_seen,
|
|
|
|
|
};
|
|
|
|
|
|
2018-03-31 04:05:28 +08:00
|
|
|
enum rxrpc_local_trace {
|
|
|
|
|
rxrpc_local_got,
|
|
|
|
|
rxrpc_local_new,
|
|
|
|
|
rxrpc_local_processing,
|
|
|
|
|
rxrpc_local_put,
|
|
|
|
|
rxrpc_local_queued,
|
|
|
|
|
};
|
|
|
|
|
|
2018-03-31 04:05:38 +08:00
|
|
|
enum rxrpc_peer_trace {
|
|
|
|
|
rxrpc_peer_got,
|
|
|
|
|
rxrpc_peer_new,
|
|
|
|
|
rxrpc_peer_processing,
|
|
|
|
|
rxrpc_peer_put,
|
|
|
|
|
};
|
|
|
|
|
|
2017-01-05 18:38:33 +08:00
|
|
|
enum rxrpc_conn_trace {
|
|
|
|
|
rxrpc_conn_got,
|
|
|
|
|
rxrpc_conn_new_client,
|
|
|
|
|
rxrpc_conn_new_service,
|
|
|
|
|
rxrpc_conn_put_client,
|
|
|
|
|
rxrpc_conn_put_service,
|
|
|
|
|
rxrpc_conn_queued,
|
2017-11-24 18:18:42 +08:00
|
|
|
rxrpc_conn_reap_service,
|
2017-01-05 18:38:33 +08:00
|
|
|
rxrpc_conn_seen,
|
|
|
|
|
};
|
|
|
|
|
|
|
|
|
|
enum rxrpc_client_trace {
|
|
|
|
|
rxrpc_client_activate_chans,
|
|
|
|
|
rxrpc_client_alloc,
|
|
|
|
|
rxrpc_client_chan_activate,
|
|
|
|
|
rxrpc_client_chan_disconnect,
|
|
|
|
|
rxrpc_client_chan_pass,
|
|
|
|
|
rxrpc_client_chan_unstarted,
|
2019-03-08 20:48:39 +08:00
|
|
|
rxrpc_client_chan_wait_failed,
|
2017-01-05 18:38:33 +08:00
|
|
|
rxrpc_client_cleanup,
|
|
|
|
|
rxrpc_client_count,
|
|
|
|
|
rxrpc_client_discard,
|
|
|
|
|
rxrpc_client_duplicate,
|
|
|
|
|
rxrpc_client_exposed,
|
|
|
|
|
rxrpc_client_replace,
|
|
|
|
|
rxrpc_client_to_active,
|
|
|
|
|
rxrpc_client_to_culled,
|
|
|
|
|
rxrpc_client_to_idle,
|
|
|
|
|
rxrpc_client_to_inactive,
|
|
|
|
|
rxrpc_client_to_upgrade,
|
|
|
|
|
rxrpc_client_to_waiting,
|
|
|
|
|
rxrpc_client_uncount,
|
|
|
|
|
};
|
|
|
|
|
|
|
|
|
|
enum rxrpc_call_trace {
|
|
|
|
|
rxrpc_call_connected,
|
|
|
|
|
rxrpc_call_error,
|
|
|
|
|
rxrpc_call_got,
|
|
|
|
|
rxrpc_call_got_kernel,
|
|
|
|
|
rxrpc_call_got_userid,
|
|
|
|
|
rxrpc_call_new_client,
|
|
|
|
|
rxrpc_call_new_service,
|
|
|
|
|
rxrpc_call_put,
|
|
|
|
|
rxrpc_call_put_kernel,
|
|
|
|
|
rxrpc_call_put_noqueue,
|
|
|
|
|
rxrpc_call_put_userid,
|
|
|
|
|
rxrpc_call_queued,
|
|
|
|
|
rxrpc_call_queued_ref,
|
|
|
|
|
rxrpc_call_release,
|
|
|
|
|
rxrpc_call_seen,
|
|
|
|
|
};
|
|
|
|
|
|
|
|
|
|
enum rxrpc_transmit_trace {
|
|
|
|
|
rxrpc_transmit_await_reply,
|
|
|
|
|
rxrpc_transmit_end,
|
|
|
|
|
rxrpc_transmit_queue,
|
|
|
|
|
rxrpc_transmit_queue_last,
|
|
|
|
|
rxrpc_transmit_rotate,
|
|
|
|
|
rxrpc_transmit_rotate_last,
|
|
|
|
|
rxrpc_transmit_wait,
|
|
|
|
|
};
|
|
|
|
|
|
|
|
|
|
enum rxrpc_receive_trace {
|
|
|
|
|
rxrpc_receive_end,
|
|
|
|
|
rxrpc_receive_front,
|
|
|
|
|
rxrpc_receive_incoming,
|
|
|
|
|
rxrpc_receive_queue,
|
|
|
|
|
rxrpc_receive_queue_last,
|
|
|
|
|
rxrpc_receive_rotate,
|
|
|
|
|
};
|
|
|
|
|
|
|
|
|
|
enum rxrpc_recvmsg_trace {
|
|
|
|
|
rxrpc_recvmsg_cont,
|
|
|
|
|
rxrpc_recvmsg_data_return,
|
|
|
|
|
rxrpc_recvmsg_dequeue,
|
|
|
|
|
rxrpc_recvmsg_enter,
|
|
|
|
|
rxrpc_recvmsg_full,
|
|
|
|
|
rxrpc_recvmsg_hole,
|
|
|
|
|
rxrpc_recvmsg_next,
|
rxrpc: Fix deadlock between call creation and sendmsg/recvmsg
All the routines by which rxrpc is accessed from the outside are serialised
by means of the socket lock (sendmsg, recvmsg, bind,
rxrpc_kernel_begin_call(), ...) and this presents a problem:
(1) If a number of calls on the same socket are in the process of
connection to the same peer, a maximum of four concurrent live calls
are permitted before further calls need to wait for a slot.
(2) If a call is waiting for a slot, it is deep inside sendmsg() or
rxrpc_kernel_begin_call() and the entry function is holding the socket
lock.
(3) sendmsg() and recvmsg() or the in-kernel equivalents are prevented
from servicing the other calls as they need to take the socket lock to
do so.
(4) The socket is stuck until a call is aborted and makes its slot
available to the waiter.
Fix this by:
(1) Provide each call with a mutex ('user_mutex') that arbitrates access
by the users of rxrpc separately for each specific call.
(2) Make rxrpc_sendmsg() and rxrpc_recvmsg() unlock the socket as soon as
they've got a call and taken its mutex.
Note that I'm returning EWOULDBLOCK from recvmsg() if MSG_DONTWAIT is
set but someone else has the lock. Should I instead only return
EWOULDBLOCK if there's nothing currently to be done on a socket, and
sleep in this particular instance because there is something to be
done, but we appear to be blocked by the interrupt handler doing its
ping?
(3) Make rxrpc_new_client_call() unlock the socket after allocating a new
call, locking its user mutex and adding it to the socket's call tree.
The call is returned locked so that sendmsg() can add data to it
immediately.
From the moment the call is in the socket tree, it is subject to
access by sendmsg() and recvmsg() - even if it isn't connected yet.
(4) Lock new service calls in the UDP data_ready handler (in
rxrpc_new_incoming_call()) because they may already be in the socket's
tree and the data_ready handler makes them live immediately if a user
ID has already been preassigned.
Note that the new call is locked before any notifications are sent
that it is live, so doing mutex_trylock() *ought* to always succeed.
Userspace is prevented from doing sendmsg() on calls that are in a
too-early state in rxrpc_do_sendmsg().
(5) Make rxrpc_new_incoming_call() return the call with the user mutex
held so that a ping can be scheduled immediately under it.
Note that it might be worth moving the ping call into
rxrpc_new_incoming_call() and then we can drop the mutex there.
(6) Make rxrpc_accept_call() take the lock on the call it is accepting and
release the socket after adding the call to the socket's tree. This
is slightly tricky as we've dequeued the call by that point and have
to requeue it.
Note that requeuing emits a trace event.
(7) Make rxrpc_kernel_send_data() and rxrpc_kernel_recv_data() take the
new mutex immediately and don't bother with the socket mutex at all.
This patch has the nice bonus that calls on the same socket are now to some
extent parallelisable.
Note that we might want to move rxrpc_service_prealloc() calls out from the
socket lock and give it its own lock, so that we don't hang progress in
other calls because we're waiting for the allocator.
We probably also want to avoid calling rxrpc_notify_socket() from within
the socket lock (rxrpc_accept_call()).
Signed-off-by: David Howells <dhowells@redhat.com>
Tested-by: Marc Dionne <marc.c.dionne@auristor.com>
Signed-off-by: David S. Miller <davem@davemloft.net>
2017-02-27 23:43:06 +08:00
|
|
|
rxrpc_recvmsg_requeue,
|
2017-01-05 18:38:33 +08:00
|
|
|
rxrpc_recvmsg_return,
|
|
|
|
|
rxrpc_recvmsg_terminal,
|
|
|
|
|
rxrpc_recvmsg_to_be_accepted,
|
|
|
|
|
rxrpc_recvmsg_wait,
|
|
|
|
|
};
|
|
|
|
|
|
|
|
|
|
enum rxrpc_rtt_tx_trace {
|
|
|
|
|
rxrpc_rtt_tx_data,
|
|
|
|
|
rxrpc_rtt_tx_ping,
|
|
|
|
|
};
|
|
|
|
|
|
|
|
|
|
enum rxrpc_rtt_rx_trace {
|
|
|
|
|
rxrpc_rtt_rx_ping_response,
|
|
|
|
|
rxrpc_rtt_rx_requested_ack,
|
|
|
|
|
};
|
|
|
|
|
|
|
|
|
|
enum rxrpc_timer_trace {
|
|
|
|
|
rxrpc_timer_begin,
|
2017-11-24 18:18:41 +08:00
|
|
|
rxrpc_timer_exp_ack,
|
|
|
|
|
rxrpc_timer_exp_hard,
|
|
|
|
|
rxrpc_timer_exp_idle,
|
2017-11-24 18:18:42 +08:00
|
|
|
rxrpc_timer_exp_keepalive,
|
2017-11-24 18:18:42 +08:00
|
|
|
rxrpc_timer_exp_lost_ack,
|
2017-11-24 18:18:41 +08:00
|
|
|
rxrpc_timer_exp_normal,
|
|
|
|
|
rxrpc_timer_exp_ping,
|
|
|
|
|
rxrpc_timer_exp_resend,
|
2017-01-05 18:38:33 +08:00
|
|
|
rxrpc_timer_expired,
|
|
|
|
|
rxrpc_timer_init_for_reply,
|
|
|
|
|
rxrpc_timer_init_for_send_reply,
|
2017-11-24 18:18:41 +08:00
|
|
|
rxrpc_timer_restart,
|
2017-01-05 18:38:33 +08:00
|
|
|
rxrpc_timer_set_for_ack,
|
2017-11-24 18:18:41 +08:00
|
|
|
rxrpc_timer_set_for_hard,
|
|
|
|
|
rxrpc_timer_set_for_idle,
|
2017-11-24 18:18:42 +08:00
|
|
|
rxrpc_timer_set_for_keepalive,
|
2017-11-24 18:18:42 +08:00
|
|
|
rxrpc_timer_set_for_lost_ack,
|
2017-11-24 18:18:41 +08:00
|
|
|
rxrpc_timer_set_for_normal,
|
2017-01-05 18:38:33 +08:00
|
|
|
rxrpc_timer_set_for_ping,
|
|
|
|
|
rxrpc_timer_set_for_resend,
|
|
|
|
|
rxrpc_timer_set_for_send,
|
|
|
|
|
};
|
|
|
|
|
|
|
|
|
|
enum rxrpc_propose_ack_trace {
|
|
|
|
|
rxrpc_propose_ack_client_tx_end,
|
|
|
|
|
rxrpc_propose_ack_input_data,
|
2018-11-13 06:33:22 +08:00
|
|
|
rxrpc_propose_ack_ping_for_check_life,
|
2017-11-24 18:18:42 +08:00
|
|
|
rxrpc_propose_ack_ping_for_keepalive,
|
2017-01-05 18:38:33 +08:00
|
|
|
rxrpc_propose_ack_ping_for_lost_ack,
|
|
|
|
|
rxrpc_propose_ack_ping_for_lost_reply,
|
|
|
|
|
rxrpc_propose_ack_ping_for_params,
|
|
|
|
|
rxrpc_propose_ack_processing_op,
|
|
|
|
|
rxrpc_propose_ack_respond_to_ack,
|
|
|
|
|
rxrpc_propose_ack_respond_to_ping,
|
|
|
|
|
rxrpc_propose_ack_retry_tx,
|
|
|
|
|
rxrpc_propose_ack_rotate_rx,
|
|
|
|
|
rxrpc_propose_ack_terminal_ack,
|
|
|
|
|
};
|
|
|
|
|
|
|
|
|
|
enum rxrpc_propose_ack_outcome {
|
|
|
|
|
rxrpc_propose_ack_subsume,
|
|
|
|
|
rxrpc_propose_ack_update,
|
|
|
|
|
rxrpc_propose_ack_use,
|
|
|
|
|
};
|
|
|
|
|
|
|
|
|
|
enum rxrpc_congest_change {
|
|
|
|
|
rxrpc_cong_begin_retransmission,
|
|
|
|
|
rxrpc_cong_cleared_nacks,
|
|
|
|
|
rxrpc_cong_new_low_nack,
|
|
|
|
|
rxrpc_cong_no_change,
|
|
|
|
|
rxrpc_cong_progress,
|
|
|
|
|
rxrpc_cong_retransmit_again,
|
|
|
|
|
rxrpc_cong_rtt_window_end,
|
|
|
|
|
rxrpc_cong_saw_nack,
|
|
|
|
|
};
|
|
|
|
|
|
2018-07-24 00:18:37 +08:00
|
|
|
enum rxrpc_tx_point {
|
|
|
|
|
rxrpc_tx_point_call_abort,
|
|
|
|
|
rxrpc_tx_point_call_ack,
|
|
|
|
|
rxrpc_tx_point_call_data_frag,
|
|
|
|
|
rxrpc_tx_point_call_data_nofrag,
|
|
|
|
|
rxrpc_tx_point_call_final_resend,
|
|
|
|
|
rxrpc_tx_point_conn_abort,
|
|
|
|
|
rxrpc_tx_point_rxkad_challenge,
|
|
|
|
|
rxrpc_tx_point_rxkad_response,
|
|
|
|
|
rxrpc_tx_point_reject,
|
|
|
|
|
rxrpc_tx_point_version_keepalive,
|
|
|
|
|
rxrpc_tx_point_version_reply,
|
2018-05-11 06:26:01 +08:00
|
|
|
};
|
|
|
|
|
|
2017-01-05 18:38:33 +08:00
|
|
|
#endif /* end __RXRPC_DECLARE_TRACE_ENUMS_ONCE_ONLY */
|
|
|
|
|
|
|
|
|
|
/*
|
|
|
|
|
* Declare tracing information enums and their string mappings for display.
|
|
|
|
|
*/
|
|
|
|
|
#define rxrpc_skb_traces \
|
|
|
|
|
EM(rxrpc_skb_rx_cleaned, "Rx CLN") \
|
|
|
|
|
EM(rxrpc_skb_rx_freed, "Rx FRE") \
|
|
|
|
|
EM(rxrpc_skb_rx_got, "Rx GOT") \
|
|
|
|
|
EM(rxrpc_skb_rx_lost, "Rx *L*") \
|
|
|
|
|
EM(rxrpc_skb_rx_purged, "Rx PUR") \
|
|
|
|
|
EM(rxrpc_skb_rx_received, "Rx RCV") \
|
|
|
|
|
EM(rxrpc_skb_rx_rotated, "Rx ROT") \
|
|
|
|
|
EM(rxrpc_skb_rx_seen, "Rx SEE") \
|
|
|
|
|
EM(rxrpc_skb_tx_cleaned, "Tx CLN") \
|
|
|
|
|
EM(rxrpc_skb_tx_freed, "Tx FRE") \
|
|
|
|
|
EM(rxrpc_skb_tx_got, "Tx GOT") \
|
|
|
|
|
EM(rxrpc_skb_tx_new, "Tx NEW") \
|
|
|
|
|
EM(rxrpc_skb_tx_rotated, "Tx ROT") \
|
|
|
|
|
E_(rxrpc_skb_tx_seen, "Tx SEE")
|
|
|
|
|
|
2018-03-31 04:05:28 +08:00
|
|
|
#define rxrpc_local_traces \
|
|
|
|
|
EM(rxrpc_local_got, "GOT") \
|
|
|
|
|
EM(rxrpc_local_new, "NEW") \
|
|
|
|
|
EM(rxrpc_local_processing, "PRO") \
|
|
|
|
|
EM(rxrpc_local_put, "PUT") \
|
|
|
|
|
E_(rxrpc_local_queued, "QUE")
|
|
|
|
|
|
2018-03-31 04:05:38 +08:00
|
|
|
#define rxrpc_peer_traces \
|
|
|
|
|
EM(rxrpc_peer_got, "GOT") \
|
|
|
|
|
EM(rxrpc_peer_new, "NEW") \
|
|
|
|
|
EM(rxrpc_peer_processing, "PRO") \
|
2018-09-27 22:13:09 +08:00
|
|
|
E_(rxrpc_peer_put, "PUT")
|
2018-03-31 04:05:38 +08:00
|
|
|
|
2017-01-05 18:38:33 +08:00
|
|
|
#define rxrpc_conn_traces \
|
|
|
|
|
EM(rxrpc_conn_got, "GOT") \
|
|
|
|
|
EM(rxrpc_conn_new_client, "NWc") \
|
|
|
|
|
EM(rxrpc_conn_new_service, "NWs") \
|
|
|
|
|
EM(rxrpc_conn_put_client, "PTc") \
|
|
|
|
|
EM(rxrpc_conn_put_service, "PTs") \
|
|
|
|
|
EM(rxrpc_conn_queued, "QUE") \
|
2017-11-24 18:18:42 +08:00
|
|
|
EM(rxrpc_conn_reap_service, "RPs") \
|
2017-01-05 18:38:33 +08:00
|
|
|
E_(rxrpc_conn_seen, "SEE")
|
|
|
|
|
|
|
|
|
|
#define rxrpc_client_traces \
|
|
|
|
|
EM(rxrpc_client_activate_chans, "Activa") \
|
|
|
|
|
EM(rxrpc_client_alloc, "Alloc ") \
|
|
|
|
|
EM(rxrpc_client_chan_activate, "ChActv") \
|
|
|
|
|
EM(rxrpc_client_chan_disconnect, "ChDisc") \
|
|
|
|
|
EM(rxrpc_client_chan_pass, "ChPass") \
|
|
|
|
|
EM(rxrpc_client_chan_unstarted, "ChUnst") \
|
2019-03-08 20:48:39 +08:00
|
|
|
EM(rxrpc_client_chan_wait_failed, "ChWtFl") \
|
2017-01-05 18:38:33 +08:00
|
|
|
EM(rxrpc_client_cleanup, "Clean ") \
|
|
|
|
|
EM(rxrpc_client_count, "Count ") \
|
|
|
|
|
EM(rxrpc_client_discard, "Discar") \
|
|
|
|
|
EM(rxrpc_client_duplicate, "Duplic") \
|
|
|
|
|
EM(rxrpc_client_exposed, "Expose") \
|
|
|
|
|
EM(rxrpc_client_replace, "Replac") \
|
|
|
|
|
EM(rxrpc_client_to_active, "->Actv") \
|
|
|
|
|
EM(rxrpc_client_to_culled, "->Cull") \
|
|
|
|
|
EM(rxrpc_client_to_idle, "->Idle") \
|
|
|
|
|
EM(rxrpc_client_to_inactive, "->Inac") \
|
|
|
|
|
EM(rxrpc_client_to_upgrade, "->Upgd") \
|
|
|
|
|
EM(rxrpc_client_to_waiting, "->Wait") \
|
|
|
|
|
E_(rxrpc_client_uncount, "Uncoun")
|
|
|
|
|
|
|
|
|
|
#define rxrpc_conn_cache_states \
|
|
|
|
|
EM(RXRPC_CONN_CLIENT_INACTIVE, "Inac") \
|
|
|
|
|
EM(RXRPC_CONN_CLIENT_WAITING, "Wait") \
|
|
|
|
|
EM(RXRPC_CONN_CLIENT_ACTIVE, "Actv") \
|
2017-06-05 21:30:49 +08:00
|
|
|
EM(RXRPC_CONN_CLIENT_UPGRADE, "Upgd") \
|
2017-01-05 18:38:33 +08:00
|
|
|
EM(RXRPC_CONN_CLIENT_CULLED, "Cull") \
|
|
|
|
|
E_(RXRPC_CONN_CLIENT_IDLE, "Idle") \
|
|
|
|
|
|
|
|
|
|
#define rxrpc_call_traces \
|
|
|
|
|
EM(rxrpc_call_connected, "CON") \
|
|
|
|
|
EM(rxrpc_call_error, "*E*") \
|
|
|
|
|
EM(rxrpc_call_got, "GOT") \
|
|
|
|
|
EM(rxrpc_call_got_kernel, "Gke") \
|
|
|
|
|
EM(rxrpc_call_got_userid, "Gus") \
|
|
|
|
|
EM(rxrpc_call_new_client, "NWc") \
|
|
|
|
|
EM(rxrpc_call_new_service, "NWs") \
|
|
|
|
|
EM(rxrpc_call_put, "PUT") \
|
|
|
|
|
EM(rxrpc_call_put_kernel, "Pke") \
|
|
|
|
|
EM(rxrpc_call_put_noqueue, "PNQ") \
|
|
|
|
|
EM(rxrpc_call_put_userid, "Pus") \
|
|
|
|
|
EM(rxrpc_call_queued, "QUE") \
|
|
|
|
|
EM(rxrpc_call_queued_ref, "QUR") \
|
|
|
|
|
EM(rxrpc_call_release, "RLS") \
|
|
|
|
|
E_(rxrpc_call_seen, "SEE")
|
|
|
|
|
|
|
|
|
|
#define rxrpc_transmit_traces \
|
|
|
|
|
EM(rxrpc_transmit_await_reply, "AWR") \
|
|
|
|
|
EM(rxrpc_transmit_end, "END") \
|
|
|
|
|
EM(rxrpc_transmit_queue, "QUE") \
|
|
|
|
|
EM(rxrpc_transmit_queue_last, "QLS") \
|
|
|
|
|
EM(rxrpc_transmit_rotate, "ROT") \
|
|
|
|
|
EM(rxrpc_transmit_rotate_last, "RLS") \
|
|
|
|
|
E_(rxrpc_transmit_wait, "WAI")
|
|
|
|
|
|
|
|
|
|
#define rxrpc_receive_traces \
|
|
|
|
|
EM(rxrpc_receive_end, "END") \
|
|
|
|
|
EM(rxrpc_receive_front, "FRN") \
|
|
|
|
|
EM(rxrpc_receive_incoming, "INC") \
|
|
|
|
|
EM(rxrpc_receive_queue, "QUE") \
|
|
|
|
|
EM(rxrpc_receive_queue_last, "QLS") \
|
|
|
|
|
E_(rxrpc_receive_rotate, "ROT")
|
|
|
|
|
|
|
|
|
|
#define rxrpc_recvmsg_traces \
|
|
|
|
|
EM(rxrpc_recvmsg_cont, "CONT") \
|
|
|
|
|
EM(rxrpc_recvmsg_data_return, "DATA") \
|
|
|
|
|
EM(rxrpc_recvmsg_dequeue, "DEQU") \
|
|
|
|
|
EM(rxrpc_recvmsg_enter, "ENTR") \
|
|
|
|
|
EM(rxrpc_recvmsg_full, "FULL") \
|
|
|
|
|
EM(rxrpc_recvmsg_hole, "HOLE") \
|
|
|
|
|
EM(rxrpc_recvmsg_next, "NEXT") \
|
rxrpc: Fix deadlock between call creation and sendmsg/recvmsg
All the routines by which rxrpc is accessed from the outside are serialised
by means of the socket lock (sendmsg, recvmsg, bind,
rxrpc_kernel_begin_call(), ...) and this presents a problem:
(1) If a number of calls on the same socket are in the process of
connection to the same peer, a maximum of four concurrent live calls
are permitted before further calls need to wait for a slot.
(2) If a call is waiting for a slot, it is deep inside sendmsg() or
rxrpc_kernel_begin_call() and the entry function is holding the socket
lock.
(3) sendmsg() and recvmsg() or the in-kernel equivalents are prevented
from servicing the other calls as they need to take the socket lock to
do so.
(4) The socket is stuck until a call is aborted and makes its slot
available to the waiter.
Fix this by:
(1) Provide each call with a mutex ('user_mutex') that arbitrates access
by the users of rxrpc separately for each specific call.
(2) Make rxrpc_sendmsg() and rxrpc_recvmsg() unlock the socket as soon as
they've got a call and taken its mutex.
Note that I'm returning EWOULDBLOCK from recvmsg() if MSG_DONTWAIT is
set but someone else has the lock. Should I instead only return
EWOULDBLOCK if there's nothing currently to be done on a socket, and
sleep in this particular instance because there is something to be
done, but we appear to be blocked by the interrupt handler doing its
ping?
(3) Make rxrpc_new_client_call() unlock the socket after allocating a new
call, locking its user mutex and adding it to the socket's call tree.
The call is returned locked so that sendmsg() can add data to it
immediately.
From the moment the call is in the socket tree, it is subject to
access by sendmsg() and recvmsg() - even if it isn't connected yet.
(4) Lock new service calls in the UDP data_ready handler (in
rxrpc_new_incoming_call()) because they may already be in the socket's
tree and the data_ready handler makes them live immediately if a user
ID has already been preassigned.
Note that the new call is locked before any notifications are sent
that it is live, so doing mutex_trylock() *ought* to always succeed.
Userspace is prevented from doing sendmsg() on calls that are in a
too-early state in rxrpc_do_sendmsg().
(5) Make rxrpc_new_incoming_call() return the call with the user mutex
held so that a ping can be scheduled immediately under it.
Note that it might be worth moving the ping call into
rxrpc_new_incoming_call() and then we can drop the mutex there.
(6) Make rxrpc_accept_call() take the lock on the call it is accepting and
release the socket after adding the call to the socket's tree. This
is slightly tricky as we've dequeued the call by that point and have
to requeue it.
Note that requeuing emits a trace event.
(7) Make rxrpc_kernel_send_data() and rxrpc_kernel_recv_data() take the
new mutex immediately and don't bother with the socket mutex at all.
This patch has the nice bonus that calls on the same socket are now to some
extent parallelisable.
Note that we might want to move rxrpc_service_prealloc() calls out from the
socket lock and give it its own lock, so that we don't hang progress in
other calls because we're waiting for the allocator.
We probably also want to avoid calling rxrpc_notify_socket() from within
the socket lock (rxrpc_accept_call()).
Signed-off-by: David Howells <dhowells@redhat.com>
Tested-by: Marc Dionne <marc.c.dionne@auristor.com>
Signed-off-by: David S. Miller <davem@davemloft.net>
2017-02-27 23:43:06 +08:00
|
|
|
EM(rxrpc_recvmsg_requeue, "REQU") \
|
2017-01-05 18:38:33 +08:00
|
|
|
EM(rxrpc_recvmsg_return, "RETN") \
|
|
|
|
|
EM(rxrpc_recvmsg_terminal, "TERM") \
|
|
|
|
|
EM(rxrpc_recvmsg_to_be_accepted, "TBAC") \
|
|
|
|
|
E_(rxrpc_recvmsg_wait, "WAIT")
|
|
|
|
|
|
|
|
|
|
#define rxrpc_rtt_tx_traces \
|
|
|
|
|
EM(rxrpc_rtt_tx_data, "DATA") \
|
|
|
|
|
E_(rxrpc_rtt_tx_ping, "PING")
|
|
|
|
|
|
|
|
|
|
#define rxrpc_rtt_rx_traces \
|
|
|
|
|
EM(rxrpc_rtt_rx_ping_response, "PONG") \
|
|
|
|
|
E_(rxrpc_rtt_rx_requested_ack, "RACK")
|
|
|
|
|
|
|
|
|
|
#define rxrpc_timer_traces \
|
|
|
|
|
EM(rxrpc_timer_begin, "Begin ") \
|
|
|
|
|
EM(rxrpc_timer_expired, "*EXPR*") \
|
2017-11-24 18:18:41 +08:00
|
|
|
EM(rxrpc_timer_exp_ack, "ExpAck") \
|
|
|
|
|
EM(rxrpc_timer_exp_hard, "ExpHrd") \
|
|
|
|
|
EM(rxrpc_timer_exp_idle, "ExpIdl") \
|
2017-11-24 18:18:42 +08:00
|
|
|
EM(rxrpc_timer_exp_keepalive, "ExpKA ") \
|
2017-11-24 18:18:42 +08:00
|
|
|
EM(rxrpc_timer_exp_lost_ack, "ExpLoA") \
|
2017-11-24 18:18:41 +08:00
|
|
|
EM(rxrpc_timer_exp_normal, "ExpNml") \
|
|
|
|
|
EM(rxrpc_timer_exp_ping, "ExpPng") \
|
|
|
|
|
EM(rxrpc_timer_exp_resend, "ExpRsn") \
|
2017-01-05 18:38:33 +08:00
|
|
|
EM(rxrpc_timer_init_for_reply, "IniRpl") \
|
|
|
|
|
EM(rxrpc_timer_init_for_send_reply, "SndRpl") \
|
2017-11-24 18:18:41 +08:00
|
|
|
EM(rxrpc_timer_restart, "Restrt") \
|
2017-01-05 18:38:33 +08:00
|
|
|
EM(rxrpc_timer_set_for_ack, "SetAck") \
|
2017-11-24 18:18:41 +08:00
|
|
|
EM(rxrpc_timer_set_for_hard, "SetHrd") \
|
|
|
|
|
EM(rxrpc_timer_set_for_idle, "SetIdl") \
|
2017-11-24 18:18:42 +08:00
|
|
|
EM(rxrpc_timer_set_for_keepalive, "KeepAl") \
|
2017-11-24 18:18:42 +08:00
|
|
|
EM(rxrpc_timer_set_for_lost_ack, "SetLoA") \
|
2017-11-24 18:18:41 +08:00
|
|
|
EM(rxrpc_timer_set_for_normal, "SetNml") \
|
2017-01-05 18:38:33 +08:00
|
|
|
EM(rxrpc_timer_set_for_ping, "SetPng") \
|
|
|
|
|
EM(rxrpc_timer_set_for_resend, "SetRTx") \
|
2017-11-24 18:18:41 +08:00
|
|
|
E_(rxrpc_timer_set_for_send, "SetSnd")
|
2017-01-05 18:38:33 +08:00
|
|
|
|
|
|
|
|
#define rxrpc_propose_ack_traces \
|
|
|
|
|
EM(rxrpc_propose_ack_client_tx_end, "ClTxEnd") \
|
|
|
|
|
EM(rxrpc_propose_ack_input_data, "DataIn ") \
|
2018-11-13 06:33:22 +08:00
|
|
|
EM(rxrpc_propose_ack_ping_for_check_life, "ChkLife") \
|
2017-11-24 18:18:42 +08:00
|
|
|
EM(rxrpc_propose_ack_ping_for_keepalive, "KeepAlv") \
|
2017-01-05 18:38:33 +08:00
|
|
|
EM(rxrpc_propose_ack_ping_for_lost_ack, "LostAck") \
|
|
|
|
|
EM(rxrpc_propose_ack_ping_for_lost_reply, "LostRpl") \
|
|
|
|
|
EM(rxrpc_propose_ack_ping_for_params, "Params ") \
|
|
|
|
|
EM(rxrpc_propose_ack_processing_op, "ProcOp ") \
|
|
|
|
|
EM(rxrpc_propose_ack_respond_to_ack, "Rsp2Ack") \
|
|
|
|
|
EM(rxrpc_propose_ack_respond_to_ping, "Rsp2Png") \
|
|
|
|
|
EM(rxrpc_propose_ack_retry_tx, "RetryTx") \
|
|
|
|
|
EM(rxrpc_propose_ack_rotate_rx, "RxAck ") \
|
|
|
|
|
E_(rxrpc_propose_ack_terminal_ack, "ClTerm ")
|
|
|
|
|
|
|
|
|
|
#define rxrpc_propose_ack_outcomes \
|
|
|
|
|
EM(rxrpc_propose_ack_subsume, " Subsume") \
|
|
|
|
|
EM(rxrpc_propose_ack_update, " Update") \
|
2018-07-24 00:18:37 +08:00
|
|
|
E_(rxrpc_propose_ack_use, " New")
|
2017-01-05 18:38:33 +08:00
|
|
|
|
|
|
|
|
#define rxrpc_congest_modes \
|
|
|
|
|
EM(RXRPC_CALL_CONGEST_AVOIDANCE, "CongAvoid") \
|
|
|
|
|
EM(RXRPC_CALL_FAST_RETRANSMIT, "FastReTx ") \
|
|
|
|
|
EM(RXRPC_CALL_PACKET_LOSS, "PktLoss ") \
|
|
|
|
|
E_(RXRPC_CALL_SLOW_START, "SlowStart")
|
|
|
|
|
|
|
|
|
|
#define rxrpc_congest_changes \
|
|
|
|
|
EM(rxrpc_cong_begin_retransmission, " Retrans") \
|
|
|
|
|
EM(rxrpc_cong_cleared_nacks, " Cleared") \
|
|
|
|
|
EM(rxrpc_cong_new_low_nack, " NewLowN") \
|
|
|
|
|
EM(rxrpc_cong_no_change, "") \
|
|
|
|
|
EM(rxrpc_cong_progress, " Progres") \
|
|
|
|
|
EM(rxrpc_cong_retransmit_again, " ReTxAgn") \
|
|
|
|
|
EM(rxrpc_cong_rtt_window_end, " RttWinE") \
|
|
|
|
|
E_(rxrpc_cong_saw_nack, " SawNack")
|
|
|
|
|
|
|
|
|
|
#define rxrpc_pkts \
|
|
|
|
|
EM(0, "?00") \
|
|
|
|
|
EM(RXRPC_PACKET_TYPE_DATA, "DATA") \
|
|
|
|
|
EM(RXRPC_PACKET_TYPE_ACK, "ACK") \
|
|
|
|
|
EM(RXRPC_PACKET_TYPE_BUSY, "BUSY") \
|
|
|
|
|
EM(RXRPC_PACKET_TYPE_ABORT, "ABORT") \
|
|
|
|
|
EM(RXRPC_PACKET_TYPE_ACKALL, "ACKALL") \
|
|
|
|
|
EM(RXRPC_PACKET_TYPE_CHALLENGE, "CHALL") \
|
|
|
|
|
EM(RXRPC_PACKET_TYPE_RESPONSE, "RESP") \
|
|
|
|
|
EM(RXRPC_PACKET_TYPE_DEBUG, "DEBUG") \
|
|
|
|
|
EM(9, "?09") \
|
|
|
|
|
EM(10, "?10") \
|
|
|
|
|
EM(11, "?11") \
|
|
|
|
|
EM(12, "?12") \
|
|
|
|
|
EM(RXRPC_PACKET_TYPE_VERSION, "VERSION") \
|
|
|
|
|
EM(14, "?14") \
|
|
|
|
|
E_(15, "?15")
|
|
|
|
|
|
|
|
|
|
#define rxrpc_ack_names \
|
|
|
|
|
EM(0, "-0-") \
|
|
|
|
|
EM(RXRPC_ACK_REQUESTED, "REQ") \
|
|
|
|
|
EM(RXRPC_ACK_DUPLICATE, "DUP") \
|
|
|
|
|
EM(RXRPC_ACK_OUT_OF_SEQUENCE, "OOS") \
|
|
|
|
|
EM(RXRPC_ACK_EXCEEDS_WINDOW, "WIN") \
|
|
|
|
|
EM(RXRPC_ACK_NOSPACE, "MEM") \
|
|
|
|
|
EM(RXRPC_ACK_PING, "PNG") \
|
|
|
|
|
EM(RXRPC_ACK_PING_RESPONSE, "PNR") \
|
|
|
|
|
EM(RXRPC_ACK_DELAY, "DLY") \
|
|
|
|
|
EM(RXRPC_ACK_IDLE, "IDL") \
|
|
|
|
|
E_(RXRPC_ACK__INVALID, "-?-")
|
|
|
|
|
|
2018-03-28 06:08:20 +08:00
|
|
|
#define rxrpc_completions \
|
|
|
|
|
EM(RXRPC_CALL_SUCCEEDED, "Succeeded") \
|
|
|
|
|
EM(RXRPC_CALL_REMOTELY_ABORTED, "RemoteAbort") \
|
|
|
|
|
EM(RXRPC_CALL_LOCALLY_ABORTED, "LocalAbort") \
|
|
|
|
|
EM(RXRPC_CALL_LOCAL_ERROR, "LocalError") \
|
|
|
|
|
E_(RXRPC_CALL_NETWORK_ERROR, "NetError")
|
|
|
|
|
|
2018-07-24 00:18:37 +08:00
|
|
|
#define rxrpc_tx_points \
|
|
|
|
|
EM(rxrpc_tx_point_call_abort, "CallAbort") \
|
|
|
|
|
EM(rxrpc_tx_point_call_ack, "CallAck") \
|
|
|
|
|
EM(rxrpc_tx_point_call_data_frag, "CallDataFrag") \
|
|
|
|
|
EM(rxrpc_tx_point_call_data_nofrag, "CallDataNofrag") \
|
|
|
|
|
EM(rxrpc_tx_point_call_final_resend, "CallFinalResend") \
|
|
|
|
|
EM(rxrpc_tx_point_conn_abort, "ConnAbort") \
|
|
|
|
|
EM(rxrpc_tx_point_reject, "Reject") \
|
|
|
|
|
EM(rxrpc_tx_point_rxkad_challenge, "RxkadChall") \
|
|
|
|
|
EM(rxrpc_tx_point_rxkad_response, "RxkadResp") \
|
|
|
|
|
EM(rxrpc_tx_point_version_keepalive, "VerKeepalive") \
|
|
|
|
|
E_(rxrpc_tx_point_version_reply, "VerReply")
|
2018-05-11 06:26:01 +08:00
|
|
|
|
2017-01-05 18:38:33 +08:00
|
|
|
/*
|
|
|
|
|
* Export enum symbols via userspace.
|
|
|
|
|
*/
|
|
|
|
|
#undef EM
|
|
|
|
|
#undef E_
|
|
|
|
|
#define EM(a, b) TRACE_DEFINE_ENUM(a);
|
|
|
|
|
#define E_(a, b) TRACE_DEFINE_ENUM(a);
|
|
|
|
|
|
|
|
|
|
rxrpc_skb_traces;
|
2018-03-31 04:05:28 +08:00
|
|
|
rxrpc_local_traces;
|
2017-01-05 18:38:33 +08:00
|
|
|
rxrpc_conn_traces;
|
|
|
|
|
rxrpc_client_traces;
|
|
|
|
|
rxrpc_call_traces;
|
|
|
|
|
rxrpc_transmit_traces;
|
|
|
|
|
rxrpc_receive_traces;
|
|
|
|
|
rxrpc_recvmsg_traces;
|
|
|
|
|
rxrpc_rtt_tx_traces;
|
|
|
|
|
rxrpc_rtt_rx_traces;
|
|
|
|
|
rxrpc_timer_traces;
|
|
|
|
|
rxrpc_propose_ack_traces;
|
|
|
|
|
rxrpc_propose_ack_outcomes;
|
2018-03-28 06:02:47 +08:00
|
|
|
rxrpc_congest_modes;
|
2017-01-05 18:38:33 +08:00
|
|
|
rxrpc_congest_changes;
|
2018-07-24 00:18:37 +08:00
|
|
|
rxrpc_tx_points;
|
2017-01-05 18:38:33 +08:00
|
|
|
|
|
|
|
|
/*
|
|
|
|
|
* Now redefine the EM() and E_() macros to map the enums to the strings that
|
|
|
|
|
* will be printed in the output.
|
|
|
|
|
*/
|
|
|
|
|
#undef EM
|
|
|
|
|
#undef E_
|
|
|
|
|
#define EM(a, b) { a, b },
|
|
|
|
|
#define E_(a, b) { a, b }
|
|
|
|
|
|
2018-03-31 04:05:28 +08:00
|
|
|
TRACE_EVENT(rxrpc_local,
|
|
|
|
|
TP_PROTO(struct rxrpc_local *local, enum rxrpc_local_trace op,
|
|
|
|
|
int usage, const void *where),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(local, op, usage, where),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
|
|
|
|
__field(unsigned int, local )
|
|
|
|
|
__field(int, op )
|
|
|
|
|
__field(int, usage )
|
|
|
|
|
__field(const void *, where )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
|
|
|
|
__entry->local = local->debug_id;
|
|
|
|
|
__entry->op = op;
|
|
|
|
|
__entry->usage = usage;
|
|
|
|
|
__entry->where = where;
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_printk("L=%08x %s u=%d sp=%pSR",
|
|
|
|
|
__entry->local,
|
|
|
|
|
__print_symbolic(__entry->op, rxrpc_local_traces),
|
|
|
|
|
__entry->usage,
|
|
|
|
|
__entry->where)
|
|
|
|
|
);
|
|
|
|
|
|
2018-03-31 04:05:38 +08:00
|
|
|
TRACE_EVENT(rxrpc_peer,
|
|
|
|
|
TP_PROTO(struct rxrpc_peer *peer, enum rxrpc_peer_trace op,
|
|
|
|
|
int usage, const void *where),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(peer, op, usage, where),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
|
|
|
|
__field(unsigned int, peer )
|
|
|
|
|
__field(int, op )
|
|
|
|
|
__field(int, usage )
|
|
|
|
|
__field(const void *, where )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
|
|
|
|
__entry->peer = peer->debug_id;
|
|
|
|
|
__entry->op = op;
|
|
|
|
|
__entry->usage = usage;
|
|
|
|
|
__entry->where = where;
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_printk("P=%08x %s u=%d sp=%pSR",
|
|
|
|
|
__entry->peer,
|
|
|
|
|
__print_symbolic(__entry->op, rxrpc_peer_traces),
|
|
|
|
|
__entry->usage,
|
|
|
|
|
__entry->where)
|
|
|
|
|
);
|
|
|
|
|
|
2016-09-17 17:49:14 +08:00
|
|
|
TRACE_EVENT(rxrpc_conn,
|
|
|
|
|
TP_PROTO(struct rxrpc_connection *conn, enum rxrpc_conn_trace op,
|
|
|
|
|
int usage, const void *where),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(conn, op, usage, where),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, conn )
|
|
|
|
|
__field(int, op )
|
|
|
|
|
__field(int, usage )
|
|
|
|
|
__field(const void *, where )
|
2016-09-17 17:49:14 +08:00
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->conn = conn->debug_id;
|
2016-09-17 17:49:14 +08:00
|
|
|
__entry->op = op;
|
|
|
|
|
__entry->usage = usage;
|
|
|
|
|
__entry->where = where;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("C=%08x %s u=%d sp=%pSR",
|
2016-09-17 17:49:14 +08:00
|
|
|
__entry->conn,
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->op, rxrpc_conn_traces),
|
2016-09-17 17:49:14 +08:00
|
|
|
__entry->usage,
|
|
|
|
|
__entry->where)
|
|
|
|
|
);
|
|
|
|
|
|
|
|
|
|
TRACE_EVENT(rxrpc_client,
|
|
|
|
|
TP_PROTO(struct rxrpc_connection *conn, int channel,
|
|
|
|
|
enum rxrpc_client_trace op),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(conn, channel, op),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, conn )
|
2016-09-17 17:49:14 +08:00
|
|
|
__field(u32, cid )
|
|
|
|
|
__field(int, channel )
|
|
|
|
|
__field(int, usage )
|
|
|
|
|
__field(enum rxrpc_client_trace, op )
|
|
|
|
|
__field(enum rxrpc_conn_cache_state, cs )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->conn = conn->debug_id;
|
2016-09-17 17:49:14 +08:00
|
|
|
__entry->channel = channel;
|
|
|
|
|
__entry->usage = atomic_read(&conn->usage);
|
|
|
|
|
__entry->op = op;
|
|
|
|
|
__entry->cid = conn->proto.cid;
|
|
|
|
|
__entry->cs = conn->cache_state;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("C=%08x h=%2d %s %s i=%08x u=%d",
|
2016-09-17 17:49:14 +08:00
|
|
|
__entry->conn,
|
|
|
|
|
__entry->channel,
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->op, rxrpc_client_traces),
|
|
|
|
|
__print_symbolic(__entry->cs, rxrpc_conn_cache_states),
|
2016-09-17 17:49:14 +08:00
|
|
|
__entry->cid,
|
|
|
|
|
__entry->usage)
|
|
|
|
|
);
|
|
|
|
|
|
2016-08-30 16:49:29 +08:00
|
|
|
TRACE_EVENT(rxrpc_call,
|
2016-09-07 21:34:21 +08:00
|
|
|
TP_PROTO(struct rxrpc_call *call, enum rxrpc_call_trace op,
|
2016-09-08 18:10:12 +08:00
|
|
|
int usage, const void *where, const void *aux),
|
2016-08-30 16:49:29 +08:00
|
|
|
|
2016-09-08 18:10:12 +08:00
|
|
|
TP_ARGS(call, op, usage, where, aux),
|
2016-08-30 16:49:29 +08:00
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2016-08-30 16:49:29 +08:00
|
|
|
__field(int, op )
|
|
|
|
|
__field(int, usage )
|
|
|
|
|
__field(const void *, where )
|
|
|
|
|
__field(const void *, aux )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2016-08-30 16:49:29 +08:00
|
|
|
__entry->op = op;
|
|
|
|
|
__entry->usage = usage;
|
|
|
|
|
__entry->where = where;
|
|
|
|
|
__entry->aux = aux;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x %s u=%d sp=%pSR a=%p",
|
2016-08-30 16:49:29 +08:00
|
|
|
__entry->call,
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->op, rxrpc_call_traces),
|
2016-08-30 16:49:29 +08:00
|
|
|
__entry->usage,
|
|
|
|
|
__entry->where,
|
|
|
|
|
__entry->aux)
|
|
|
|
|
);
|
|
|
|
|
|
2016-08-23 22:27:24 +08:00
|
|
|
TRACE_EVENT(rxrpc_skb,
|
2016-09-17 17:49:14 +08:00
|
|
|
TP_PROTO(struct sk_buff *skb, enum rxrpc_skb_trace op,
|
|
|
|
|
int usage, int mod_count, const void *where),
|
2016-08-23 22:27:24 +08:00
|
|
|
|
|
|
|
|
TP_ARGS(skb, op, usage, mod_count, where),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
|
|
|
|
__field(struct sk_buff *, skb )
|
2016-09-17 17:49:14 +08:00
|
|
|
__field(enum rxrpc_skb_trace, op )
|
2016-08-23 22:27:24 +08:00
|
|
|
__field(int, usage )
|
|
|
|
|
__field(int, mod_count )
|
|
|
|
|
__field(const void *, where )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
|
|
|
|
__entry->skb = skb;
|
|
|
|
|
__entry->op = op;
|
|
|
|
|
__entry->usage = usage;
|
|
|
|
|
__entry->mod_count = mod_count;
|
|
|
|
|
__entry->where = where;
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_printk("s=%p %s u=%d m=%d p=%pSR",
|
|
|
|
|
__entry->skb,
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->op, rxrpc_skb_traces),
|
2016-08-23 22:27:24 +08:00
|
|
|
__entry->usage,
|
|
|
|
|
__entry->mod_count,
|
|
|
|
|
__entry->where)
|
|
|
|
|
);
|
|
|
|
|
|
2016-09-08 18:10:12 +08:00
|
|
|
TRACE_EVENT(rxrpc_rx_packet,
|
|
|
|
|
TP_PROTO(struct rxrpc_skb_priv *sp),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(sp),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
|
|
|
|
__field_struct(struct rxrpc_host_header, hdr )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
|
|
|
|
memcpy(&__entry->hdr, &sp->hdr, sizeof(__entry->hdr));
|
|
|
|
|
),
|
|
|
|
|
|
2016-09-17 17:49:13 +08:00
|
|
|
TP_printk("%08x:%08x:%08x:%04x %08x %08x %02x %02x %s",
|
2016-09-08 18:10:12 +08:00
|
|
|
__entry->hdr.epoch, __entry->hdr.cid,
|
|
|
|
|
__entry->hdr.callNumber, __entry->hdr.serviceId,
|
|
|
|
|
__entry->hdr.serial, __entry->hdr.seq,
|
2016-09-17 17:49:13 +08:00
|
|
|
__entry->hdr.type, __entry->hdr.flags,
|
2017-01-05 18:38:33 +08:00
|
|
|
__entry->hdr.type <= 15 ?
|
|
|
|
|
__print_symbolic(__entry->hdr.type, rxrpc_pkts) : "?UNK")
|
2016-09-08 18:10:12 +08:00
|
|
|
);
|
|
|
|
|
|
|
|
|
|
TRACE_EVENT(rxrpc_rx_done,
|
|
|
|
|
TP_PROTO(int result, int abort_code),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(result, abort_code),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
|
|
|
|
__field(int, result )
|
|
|
|
|
__field(int, abort_code )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
|
|
|
|
__entry->result = result;
|
|
|
|
|
__entry->abort_code = abort_code;
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_printk("r=%d a=%d", __entry->result, __entry->abort_code)
|
|
|
|
|
);
|
|
|
|
|
|
2016-09-07 05:19:51 +08:00
|
|
|
TRACE_EVENT(rxrpc_abort,
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_PROTO(unsigned int call_nr, const char *why, u32 cid, u32 call_id,
|
|
|
|
|
rxrpc_seq_t seq, int abort_code, int error),
|
2016-09-07 05:19:51 +08:00
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_ARGS(call_nr, why, cid, call_id, seq, abort_code, error),
|
2016-09-07 05:19:51 +08:00
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call_nr )
|
2016-09-07 05:19:51 +08:00
|
|
|
__array(char, why, 4 )
|
|
|
|
|
__field(u32, cid )
|
|
|
|
|
__field(u32, call_id )
|
|
|
|
|
__field(rxrpc_seq_t, seq )
|
|
|
|
|
__field(int, abort_code )
|
|
|
|
|
__field(int, error )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
|
|
|
|
memcpy(__entry->why, why, 4);
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call_nr = call_nr;
|
2016-09-07 05:19:51 +08:00
|
|
|
__entry->cid = cid;
|
|
|
|
|
__entry->call_id = call_id;
|
|
|
|
|
__entry->abort_code = abort_code;
|
|
|
|
|
__entry->error = error;
|
|
|
|
|
__entry->seq = seq;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x %08x:%08x s=%u a=%d e=%d %s",
|
|
|
|
|
__entry->call_nr,
|
2016-09-07 05:19:51 +08:00
|
|
|
__entry->cid, __entry->call_id, __entry->seq,
|
|
|
|
|
__entry->abort_code, __entry->error, __entry->why)
|
|
|
|
|
);
|
|
|
|
|
|
2018-03-28 06:08:20 +08:00
|
|
|
TRACE_EVENT(rxrpc_call_complete,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
|
|
|
|
__field(unsigned int, call )
|
|
|
|
|
__field(enum rxrpc_call_completion, compl )
|
|
|
|
|
__field(int, error )
|
|
|
|
|
__field(u32, abort_code )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
|
|
|
|
__entry->call = call->debug_id;
|
|
|
|
|
__entry->compl = call->completion;
|
|
|
|
|
__entry->error = call->error;
|
|
|
|
|
__entry->abort_code = call->abort_code;
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_printk("c=%08x %s r=%d ac=%d",
|
|
|
|
|
__entry->call,
|
|
|
|
|
__print_symbolic(__entry->compl, rxrpc_completions),
|
|
|
|
|
__entry->error,
|
|
|
|
|
__entry->abort_code)
|
|
|
|
|
);
|
|
|
|
|
|
2016-09-17 17:49:13 +08:00
|
|
|
TRACE_EVENT(rxrpc_transmit,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call, enum rxrpc_transmit_trace why),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call, why),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2016-09-17 17:49:13 +08:00
|
|
|
__field(enum rxrpc_transmit_trace, why )
|
|
|
|
|
__field(rxrpc_seq_t, tx_hard_ack )
|
|
|
|
|
__field(rxrpc_seq_t, tx_top )
|
2017-01-05 18:38:34 +08:00
|
|
|
__field(int, tx_winsize )
|
2016-09-17 17:49:13 +08:00
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2016-09-17 17:49:13 +08:00
|
|
|
__entry->why = why;
|
|
|
|
|
__entry->tx_hard_ack = call->tx_hard_ack;
|
|
|
|
|
__entry->tx_top = call->tx_top;
|
2017-01-05 18:38:34 +08:00
|
|
|
__entry->tx_winsize = call->tx_winsize;
|
2016-09-17 17:49:13 +08:00
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x %s f=%08x n=%u/%u",
|
2016-09-17 17:49:13 +08:00
|
|
|
__entry->call,
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->why, rxrpc_transmit_traces),
|
2016-09-17 17:49:13 +08:00
|
|
|
__entry->tx_hard_ack + 1,
|
2017-01-05 18:38:34 +08:00
|
|
|
__entry->tx_top - __entry->tx_hard_ack,
|
|
|
|
|
__entry->tx_winsize)
|
|
|
|
|
);
|
|
|
|
|
|
|
|
|
|
TRACE_EVENT(rxrpc_rx_data,
|
2018-07-24 00:18:37 +08:00
|
|
|
TP_PROTO(unsigned int call, rxrpc_seq_t seq,
|
2017-01-05 18:38:34 +08:00
|
|
|
rxrpc_serial_t serial, u8 flags, u8 anno),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call, seq, serial, flags, anno),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2017-01-05 18:38:34 +08:00
|
|
|
__field(rxrpc_seq_t, seq )
|
|
|
|
|
__field(rxrpc_serial_t, serial )
|
|
|
|
|
__field(u8, flags )
|
|
|
|
|
__field(u8, anno )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-07-24 00:18:37 +08:00
|
|
|
__entry->call = call;
|
2017-01-05 18:38:34 +08:00
|
|
|
__entry->seq = seq;
|
|
|
|
|
__entry->serial = serial;
|
|
|
|
|
__entry->flags = flags;
|
|
|
|
|
__entry->anno = anno;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x DATA %08x q=%08x fl=%02x a=%02x",
|
2017-01-05 18:38:34 +08:00
|
|
|
__entry->call,
|
|
|
|
|
__entry->serial,
|
|
|
|
|
__entry->seq,
|
|
|
|
|
__entry->flags,
|
|
|
|
|
__entry->anno)
|
2016-09-17 17:49:13 +08:00
|
|
|
);
|
|
|
|
|
|
2016-09-17 17:49:13 +08:00
|
|
|
TRACE_EVENT(rxrpc_rx_ack,
|
2017-01-05 18:38:34 +08:00
|
|
|
TP_PROTO(struct rxrpc_call *call,
|
|
|
|
|
rxrpc_serial_t serial, rxrpc_serial_t ack_serial,
|
|
|
|
|
rxrpc_seq_t first, rxrpc_seq_t prev, u8 reason, u8 n_acks),
|
2016-09-17 17:49:13 +08:00
|
|
|
|
2017-01-05 18:38:34 +08:00
|
|
|
TP_ARGS(call, serial, ack_serial, first, prev, reason, n_acks),
|
2016-09-17 17:49:13 +08:00
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2017-01-05 18:38:34 +08:00
|
|
|
__field(rxrpc_serial_t, serial )
|
|
|
|
|
__field(rxrpc_serial_t, ack_serial )
|
2016-09-17 17:49:13 +08:00
|
|
|
__field(rxrpc_seq_t, first )
|
2017-01-05 18:38:34 +08:00
|
|
|
__field(rxrpc_seq_t, prev )
|
2016-09-17 17:49:13 +08:00
|
|
|
__field(u8, reason )
|
|
|
|
|
__field(u8, n_acks )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2017-01-05 18:38:34 +08:00
|
|
|
__entry->serial = serial;
|
|
|
|
|
__entry->ack_serial = ack_serial;
|
2016-09-17 17:49:13 +08:00
|
|
|
__entry->first = first;
|
2017-01-05 18:38:34 +08:00
|
|
|
__entry->prev = prev;
|
2016-09-17 17:49:13 +08:00
|
|
|
__entry->reason = reason;
|
|
|
|
|
__entry->n_acks = n_acks;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x %08x %s r=%08x f=%08x p=%08x n=%u",
|
2016-09-17 17:49:13 +08:00
|
|
|
__entry->call,
|
2017-01-05 18:38:34 +08:00
|
|
|
__entry->serial,
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->reason, rxrpc_ack_names),
|
2017-01-05 18:38:34 +08:00
|
|
|
__entry->ack_serial,
|
2016-09-17 17:49:13 +08:00
|
|
|
__entry->first,
|
2017-01-05 18:38:34 +08:00
|
|
|
__entry->prev,
|
2016-09-17 17:49:13 +08:00
|
|
|
__entry->n_acks)
|
|
|
|
|
);
|
|
|
|
|
|
2017-04-06 17:12:00 +08:00
|
|
|
TRACE_EVENT(rxrpc_rx_abort,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call, rxrpc_serial_t serial,
|
|
|
|
|
u32 abort_code),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call, serial, abort_code),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2017-04-06 17:12:00 +08:00
|
|
|
__field(rxrpc_serial_t, serial )
|
|
|
|
|
__field(u32, abort_code )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2017-04-06 17:12:00 +08:00
|
|
|
__entry->serial = serial;
|
|
|
|
|
__entry->abort_code = abort_code;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x ABORT %08x ac=%d",
|
2017-04-06 17:12:00 +08:00
|
|
|
__entry->call,
|
|
|
|
|
__entry->serial,
|
|
|
|
|
__entry->abort_code)
|
|
|
|
|
);
|
|
|
|
|
|
2017-04-06 17:12:00 +08:00
|
|
|
TRACE_EVENT(rxrpc_rx_rwind_change,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call, rxrpc_serial_t serial,
|
|
|
|
|
u32 rwind, bool wake),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call, serial, rwind, wake),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2017-04-06 17:12:00 +08:00
|
|
|
__field(rxrpc_serial_t, serial )
|
|
|
|
|
__field(u32, rwind )
|
|
|
|
|
__field(bool, wake )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2017-04-06 17:12:00 +08:00
|
|
|
__entry->serial = serial;
|
|
|
|
|
__entry->rwind = rwind;
|
|
|
|
|
__entry->wake = wake;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x %08x rw=%u%s",
|
2017-04-06 17:12:00 +08:00
|
|
|
__entry->call,
|
|
|
|
|
__entry->serial,
|
|
|
|
|
__entry->rwind,
|
|
|
|
|
__entry->wake ? " wake" : "")
|
|
|
|
|
);
|
|
|
|
|
|
2018-07-24 00:18:37 +08:00
|
|
|
TRACE_EVENT(rxrpc_tx_packet,
|
|
|
|
|
TP_PROTO(unsigned int call_id, struct rxrpc_wire_header *whdr,
|
|
|
|
|
enum rxrpc_tx_point where),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call_id, whdr, where),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
|
|
|
|
__field(unsigned int, call )
|
|
|
|
|
__field(enum rxrpc_tx_point, where )
|
|
|
|
|
__field_struct(struct rxrpc_wire_header, whdr )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
|
|
|
|
__entry->call = call_id;
|
|
|
|
|
memcpy(&__entry->whdr, whdr, sizeof(__entry->whdr));
|
2018-10-09 02:44:39 +08:00
|
|
|
__entry->where = where;
|
2018-07-24 00:18:37 +08:00
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_printk("c=%08x %08x:%08x:%08x:%04x %08x %08x %02x %02x %s %s",
|
|
|
|
|
__entry->call,
|
|
|
|
|
ntohl(__entry->whdr.epoch),
|
|
|
|
|
ntohl(__entry->whdr.cid),
|
|
|
|
|
ntohl(__entry->whdr.callNumber),
|
|
|
|
|
ntohs(__entry->whdr.serviceId),
|
|
|
|
|
ntohl(__entry->whdr.serial),
|
|
|
|
|
ntohl(__entry->whdr.seq),
|
|
|
|
|
__entry->whdr.type, __entry->whdr.flags,
|
|
|
|
|
__entry->whdr.type <= 15 ?
|
|
|
|
|
__print_symbolic(__entry->whdr.type, rxrpc_pkts) : "?UNK",
|
|
|
|
|
__print_symbolic(__entry->where, rxrpc_tx_points))
|
|
|
|
|
);
|
|
|
|
|
|
2016-09-23 19:39:22 +08:00
|
|
|
TRACE_EVENT(rxrpc_tx_data,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call, rxrpc_seq_t seq,
|
2016-09-30 05:37:15 +08:00
|
|
|
rxrpc_serial_t serial, u8 flags, bool retrans, bool lose),
|
2016-09-23 19:39:22 +08:00
|
|
|
|
2016-09-30 05:37:15 +08:00
|
|
|
TP_ARGS(call, seq, serial, flags, retrans, lose),
|
2016-09-23 19:39:22 +08:00
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2016-09-23 19:39:22 +08:00
|
|
|
__field(rxrpc_seq_t, seq )
|
|
|
|
|
__field(rxrpc_serial_t, serial )
|
2018-07-24 00:18:37 +08:00
|
|
|
__field(u32, cid )
|
|
|
|
|
__field(u32, call_id )
|
2016-09-23 19:39:22 +08:00
|
|
|
__field(u8, flags )
|
2016-09-30 05:37:15 +08:00
|
|
|
__field(bool, retrans )
|
2016-09-23 19:39:22 +08:00
|
|
|
__field(bool, lose )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2018-07-24 00:18:37 +08:00
|
|
|
__entry->cid = call->cid;
|
|
|
|
|
__entry->call_id = call->call_id;
|
2016-09-23 19:39:22 +08:00
|
|
|
__entry->seq = seq;
|
|
|
|
|
__entry->serial = serial;
|
|
|
|
|
__entry->flags = flags;
|
2016-09-30 05:37:15 +08:00
|
|
|
__entry->retrans = retrans;
|
2016-09-23 19:39:22 +08:00
|
|
|
__entry->lose = lose;
|
|
|
|
|
),
|
|
|
|
|
|
2018-07-24 00:18:37 +08:00
|
|
|
TP_printk("c=%08x DATA %08x:%08x %08x q=%08x fl=%02x%s%s",
|
2016-09-23 19:39:22 +08:00
|
|
|
__entry->call,
|
2018-07-24 00:18:37 +08:00
|
|
|
__entry->cid,
|
|
|
|
|
__entry->call_id,
|
2016-09-23 19:39:22 +08:00
|
|
|
__entry->serial,
|
|
|
|
|
__entry->seq,
|
|
|
|
|
__entry->flags,
|
2016-09-30 15:50:42 +08:00
|
|
|
__entry->retrans ? " *RETRANS*" : "",
|
2016-09-23 19:39:22 +08:00
|
|
|
__entry->lose ? " *LOSE*" : "")
|
|
|
|
|
);
|
|
|
|
|
|
2016-09-17 17:49:13 +08:00
|
|
|
TRACE_EVENT(rxrpc_tx_ack,
|
2018-07-24 00:18:37 +08:00
|
|
|
TP_PROTO(unsigned int call, rxrpc_serial_t serial,
|
2016-09-23 19:39:22 +08:00
|
|
|
rxrpc_seq_t ack_first, rxrpc_serial_t ack_serial,
|
|
|
|
|
u8 reason, u8 n_acks),
|
2016-09-17 17:49:13 +08:00
|
|
|
|
2016-09-23 19:39:22 +08:00
|
|
|
TP_ARGS(call, serial, ack_first, ack_serial, reason, n_acks),
|
2016-09-17 17:49:13 +08:00
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2016-09-17 17:49:13 +08:00
|
|
|
__field(rxrpc_serial_t, serial )
|
2016-09-23 19:39:22 +08:00
|
|
|
__field(rxrpc_seq_t, ack_first )
|
|
|
|
|
__field(rxrpc_serial_t, ack_serial )
|
2016-09-17 17:49:13 +08:00
|
|
|
__field(u8, reason )
|
|
|
|
|
__field(u8, n_acks )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-07-24 00:18:37 +08:00
|
|
|
__entry->call = call;
|
2016-09-17 17:49:13 +08:00
|
|
|
__entry->serial = serial;
|
2016-09-23 19:39:22 +08:00
|
|
|
__entry->ack_first = ack_first;
|
|
|
|
|
__entry->ack_serial = ack_serial;
|
2016-09-17 17:49:13 +08:00
|
|
|
__entry->reason = reason;
|
|
|
|
|
__entry->n_acks = n_acks;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk(" c=%08x ACK %08x %s f=%08x r=%08x n=%u",
|
2016-09-17 17:49:13 +08:00
|
|
|
__entry->call,
|
|
|
|
|
__entry->serial,
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->reason, rxrpc_ack_names),
|
2016-09-23 19:39:22 +08:00
|
|
|
__entry->ack_first,
|
|
|
|
|
__entry->ack_serial,
|
2016-09-17 17:49:13 +08:00
|
|
|
__entry->n_acks)
|
|
|
|
|
);
|
|
|
|
|
|
2016-09-17 17:49:13 +08:00
|
|
|
TRACE_EVENT(rxrpc_receive,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call, enum rxrpc_receive_trace why,
|
|
|
|
|
rxrpc_serial_t serial, rxrpc_seq_t seq),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call, why, serial, seq),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2016-09-17 17:49:13 +08:00
|
|
|
__field(enum rxrpc_receive_trace, why )
|
|
|
|
|
__field(rxrpc_serial_t, serial )
|
|
|
|
|
__field(rxrpc_seq_t, seq )
|
|
|
|
|
__field(rxrpc_seq_t, hard_ack )
|
|
|
|
|
__field(rxrpc_seq_t, top )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2016-09-17 17:49:13 +08:00
|
|
|
__entry->why = why;
|
|
|
|
|
__entry->serial = serial;
|
|
|
|
|
__entry->seq = seq;
|
|
|
|
|
__entry->hard_ack = call->rx_hard_ack;
|
|
|
|
|
__entry->top = call->rx_top;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x %s r=%08x q=%08x w=%08x-%08x",
|
2016-09-17 17:49:13 +08:00
|
|
|
__entry->call,
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->why, rxrpc_receive_traces),
|
2016-09-17 17:49:13 +08:00
|
|
|
__entry->serial,
|
|
|
|
|
__entry->seq,
|
|
|
|
|
__entry->hard_ack,
|
|
|
|
|
__entry->top)
|
|
|
|
|
);
|
|
|
|
|
|
2016-09-17 18:13:31 +08:00
|
|
|
TRACE_EVENT(rxrpc_recvmsg,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call, enum rxrpc_recvmsg_trace why,
|
|
|
|
|
rxrpc_seq_t seq, unsigned int offset, unsigned int len,
|
|
|
|
|
int ret),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call, why, seq, offset, len, ret),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2016-09-17 18:13:31 +08:00
|
|
|
__field(enum rxrpc_recvmsg_trace, why )
|
|
|
|
|
__field(rxrpc_seq_t, seq )
|
|
|
|
|
__field(unsigned int, offset )
|
|
|
|
|
__field(unsigned int, len )
|
|
|
|
|
__field(int, ret )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2016-09-17 18:13:31 +08:00
|
|
|
__entry->why = why;
|
|
|
|
|
__entry->seq = seq;
|
|
|
|
|
__entry->offset = offset;
|
|
|
|
|
__entry->len = len;
|
|
|
|
|
__entry->ret = ret;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x %s q=%08x o=%u l=%u ret=%d",
|
2016-09-17 18:13:31 +08:00
|
|
|
__entry->call,
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->why, rxrpc_recvmsg_traces),
|
2016-09-17 18:13:31 +08:00
|
|
|
__entry->seq,
|
|
|
|
|
__entry->offset,
|
|
|
|
|
__entry->len,
|
|
|
|
|
__entry->ret)
|
|
|
|
|
);
|
|
|
|
|
|
2016-09-22 07:41:53 +08:00
|
|
|
TRACE_EVENT(rxrpc_rtt_tx,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call, enum rxrpc_rtt_tx_trace why,
|
|
|
|
|
rxrpc_serial_t send_serial),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call, why, send_serial),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2016-09-22 07:41:53 +08:00
|
|
|
__field(enum rxrpc_rtt_tx_trace, why )
|
|
|
|
|
__field(rxrpc_serial_t, send_serial )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2016-09-22 07:41:53 +08:00
|
|
|
__entry->why = why;
|
|
|
|
|
__entry->send_serial = send_serial;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x %s sr=%08x",
|
2016-09-22 07:41:53 +08:00
|
|
|
__entry->call,
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->why, rxrpc_rtt_tx_traces),
|
2016-09-22 07:41:53 +08:00
|
|
|
__entry->send_serial)
|
|
|
|
|
);
|
|
|
|
|
|
|
|
|
|
TRACE_EVENT(rxrpc_rtt_rx,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call, enum rxrpc_rtt_rx_trace why,
|
|
|
|
|
rxrpc_serial_t send_serial, rxrpc_serial_t resp_serial,
|
|
|
|
|
s64 rtt, u8 nr, s64 avg),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call, why, send_serial, resp_serial, rtt, nr, avg),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2016-09-22 07:41:53 +08:00
|
|
|
__field(enum rxrpc_rtt_rx_trace, why )
|
|
|
|
|
__field(u8, nr )
|
|
|
|
|
__field(rxrpc_serial_t, send_serial )
|
|
|
|
|
__field(rxrpc_serial_t, resp_serial )
|
|
|
|
|
__field(s64, rtt )
|
|
|
|
|
__field(u64, avg )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2016-09-22 07:41:53 +08:00
|
|
|
__entry->why = why;
|
|
|
|
|
__entry->send_serial = send_serial;
|
|
|
|
|
__entry->resp_serial = resp_serial;
|
|
|
|
|
__entry->rtt = rtt;
|
|
|
|
|
__entry->nr = nr;
|
|
|
|
|
__entry->avg = avg;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x %s sr=%08x rr=%08x rtt=%lld nr=%u avg=%lld",
|
2016-09-22 07:41:53 +08:00
|
|
|
__entry->call,
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->why, rxrpc_rtt_rx_traces),
|
2016-09-22 07:41:53 +08:00
|
|
|
__entry->send_serial,
|
|
|
|
|
__entry->resp_serial,
|
|
|
|
|
__entry->rtt,
|
|
|
|
|
__entry->nr,
|
|
|
|
|
__entry->avg)
|
|
|
|
|
);
|
|
|
|
|
|
2016-09-23 22:22:36 +08:00
|
|
|
TRACE_EVENT(rxrpc_timer,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call, enum rxrpc_timer_trace why,
|
2017-11-24 18:18:41 +08:00
|
|
|
unsigned long now),
|
2016-09-23 22:22:36 +08:00
|
|
|
|
2017-11-24 18:18:41 +08:00
|
|
|
TP_ARGS(call, why, now),
|
2016-09-23 22:22:36 +08:00
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2016-09-23 22:22:36 +08:00
|
|
|
__field(enum rxrpc_timer_trace, why )
|
2017-11-24 18:18:41 +08:00
|
|
|
__field(long, now )
|
|
|
|
|
__field(long, ack_at )
|
2017-11-24 18:18:42 +08:00
|
|
|
__field(long, ack_lost_at )
|
2017-11-24 18:18:41 +08:00
|
|
|
__field(long, resend_at )
|
|
|
|
|
__field(long, ping_at )
|
|
|
|
|
__field(long, expect_rx_by )
|
|
|
|
|
__field(long, expect_req_by )
|
|
|
|
|
__field(long, expect_term_by )
|
|
|
|
|
__field(long, timer )
|
2016-09-23 22:22:36 +08:00
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2017-11-24 18:18:41 +08:00
|
|
|
__entry->why = why;
|
|
|
|
|
__entry->now = now;
|
|
|
|
|
__entry->ack_at = call->ack_at;
|
2017-11-24 18:18:42 +08:00
|
|
|
__entry->ack_lost_at = call->ack_lost_at;
|
2017-11-24 18:18:41 +08:00
|
|
|
__entry->resend_at = call->resend_at;
|
|
|
|
|
__entry->expect_rx_by = call->expect_rx_by;
|
|
|
|
|
__entry->expect_req_by = call->expect_req_by;
|
|
|
|
|
__entry->expect_term_by = call->expect_term_by;
|
|
|
|
|
__entry->timer = call->timer.expires;
|
2016-09-23 22:22:36 +08:00
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x %s a=%ld la=%ld r=%ld xr=%ld xq=%ld xt=%ld t=%ld",
|
2016-09-23 22:22:36 +08:00
|
|
|
__entry->call,
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->why, rxrpc_timer_traces),
|
2017-11-24 18:18:41 +08:00
|
|
|
__entry->ack_at - __entry->now,
|
2017-11-24 18:18:42 +08:00
|
|
|
__entry->ack_lost_at - __entry->now,
|
2017-11-24 18:18:41 +08:00
|
|
|
__entry->resend_at - __entry->now,
|
|
|
|
|
__entry->expect_rx_by - __entry->now,
|
|
|
|
|
__entry->expect_req_by - __entry->now,
|
|
|
|
|
__entry->expect_term_by - __entry->now,
|
|
|
|
|
__entry->timer - __entry->now)
|
2016-09-23 22:22:36 +08:00
|
|
|
);
|
|
|
|
|
|
2016-09-23 19:39:22 +08:00
|
|
|
TRACE_EVENT(rxrpc_rx_lose,
|
|
|
|
|
TP_PROTO(struct rxrpc_skb_priv *sp),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(sp),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
|
|
|
|
__field_struct(struct rxrpc_host_header, hdr )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
|
|
|
|
memcpy(&__entry->hdr, &sp->hdr, sizeof(__entry->hdr));
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_printk("%08x:%08x:%08x:%04x %08x %08x %02x %02x %s *LOSE*",
|
|
|
|
|
__entry->hdr.epoch, __entry->hdr.cid,
|
|
|
|
|
__entry->hdr.callNumber, __entry->hdr.serviceId,
|
|
|
|
|
__entry->hdr.serial, __entry->hdr.seq,
|
|
|
|
|
__entry->hdr.type, __entry->hdr.flags,
|
2017-01-05 18:38:33 +08:00
|
|
|
__entry->hdr.type <= 15 ?
|
|
|
|
|
__print_symbolic(__entry->hdr.type, rxrpc_pkts) : "?UNK")
|
2016-09-23 19:39:22 +08:00
|
|
|
);
|
|
|
|
|
|
2016-09-23 20:50:40 +08:00
|
|
|
TRACE_EVENT(rxrpc_propose_ack,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call, enum rxrpc_propose_ack_trace why,
|
|
|
|
|
u8 ack_reason, rxrpc_serial_t serial, bool immediate,
|
|
|
|
|
bool background, enum rxrpc_propose_ack_outcome outcome),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call, why, ack_reason, serial, immediate, background,
|
|
|
|
|
outcome),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2016-09-23 20:50:40 +08:00
|
|
|
__field(enum rxrpc_propose_ack_trace, why )
|
|
|
|
|
__field(rxrpc_serial_t, serial )
|
|
|
|
|
__field(u8, ack_reason )
|
|
|
|
|
__field(bool, immediate )
|
|
|
|
|
__field(bool, background )
|
|
|
|
|
__field(enum rxrpc_propose_ack_outcome, outcome )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2016-09-23 20:50:40 +08:00
|
|
|
__entry->why = why;
|
|
|
|
|
__entry->serial = serial;
|
|
|
|
|
__entry->ack_reason = ack_reason;
|
|
|
|
|
__entry->immediate = immediate;
|
|
|
|
|
__entry->background = background;
|
|
|
|
|
__entry->outcome = outcome;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x %s %s r=%08x i=%u b=%u%s",
|
2016-09-23 20:50:40 +08:00
|
|
|
__entry->call,
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->why, rxrpc_propose_ack_traces),
|
|
|
|
|
__print_symbolic(__entry->ack_reason, rxrpc_ack_names),
|
2016-09-23 20:50:40 +08:00
|
|
|
__entry->serial,
|
|
|
|
|
__entry->immediate,
|
|
|
|
|
__entry->background,
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->outcome, rxrpc_propose_ack_outcomes))
|
2016-09-23 20:50:40 +08:00
|
|
|
);
|
|
|
|
|
|
2016-09-23 20:58:55 +08:00
|
|
|
TRACE_EVENT(rxrpc_retransmit,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call, rxrpc_seq_t seq, u8 annotation,
|
|
|
|
|
s64 expiry),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call, seq, annotation, expiry),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2016-09-23 20:58:55 +08:00
|
|
|
__field(rxrpc_seq_t, seq )
|
|
|
|
|
__field(u8, annotation )
|
|
|
|
|
__field(s64, expiry )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2016-09-23 20:58:55 +08:00
|
|
|
__entry->seq = seq;
|
|
|
|
|
__entry->annotation = annotation;
|
|
|
|
|
__entry->expiry = expiry;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x q=%x a=%02x xp=%lld",
|
2016-09-23 20:58:55 +08:00
|
|
|
__entry->call,
|
|
|
|
|
__entry->seq,
|
|
|
|
|
__entry->annotation,
|
|
|
|
|
__entry->expiry)
|
|
|
|
|
);
|
|
|
|
|
|
2016-09-25 01:05:27 +08:00
|
|
|
TRACE_EVENT(rxrpc_congest,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call, struct rxrpc_ack_summary *summary,
|
|
|
|
|
rxrpc_serial_t ack_serial, enum rxrpc_congest_change change),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call, summary, ack_serial, change),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2016-09-25 01:05:27 +08:00
|
|
|
__field(enum rxrpc_congest_change, change )
|
|
|
|
|
__field(rxrpc_seq_t, hard_ack )
|
|
|
|
|
__field(rxrpc_seq_t, top )
|
|
|
|
|
__field(rxrpc_seq_t, lowest_nak )
|
|
|
|
|
__field(rxrpc_serial_t, ack_serial )
|
|
|
|
|
__field_struct(struct rxrpc_ack_summary, sum )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2016-09-25 01:05:27 +08:00
|
|
|
__entry->change = change;
|
|
|
|
|
__entry->hard_ack = call->tx_hard_ack;
|
|
|
|
|
__entry->top = call->tx_top;
|
|
|
|
|
__entry->lowest_nak = call->acks_lowest_nak;
|
|
|
|
|
__entry->ack_serial = ack_serial;
|
|
|
|
|
memcpy(&__entry->sum, summary, sizeof(__entry->sum));
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x r=%08x %s q=%08x %s cw=%u ss=%u nr=%u,%u nw=%u,%u r=%u b=%u u=%u d=%u l=%x%s%s%s",
|
2016-09-25 01:05:27 +08:00
|
|
|
__entry->call,
|
|
|
|
|
__entry->ack_serial,
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->sum.ack_reason, rxrpc_ack_names),
|
2016-09-25 01:05:27 +08:00
|
|
|
__entry->hard_ack,
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->sum.mode, rxrpc_congest_modes),
|
2016-09-25 01:05:27 +08:00
|
|
|
__entry->sum.cwnd,
|
|
|
|
|
__entry->sum.ssthresh,
|
|
|
|
|
__entry->sum.nr_acks, __entry->sum.nr_nacks,
|
|
|
|
|
__entry->sum.nr_new_acks, __entry->sum.nr_new_nacks,
|
|
|
|
|
__entry->sum.nr_rot_new_acks,
|
|
|
|
|
__entry->top - __entry->hard_ack,
|
|
|
|
|
__entry->sum.cumulative_acks,
|
|
|
|
|
__entry->sum.dup_acks,
|
|
|
|
|
__entry->lowest_nak, __entry->sum.new_low_nack ? "!" : "",
|
2017-01-05 18:38:33 +08:00
|
|
|
__print_symbolic(__entry->change, rxrpc_congest_changes),
|
2016-09-25 01:05:27 +08:00
|
|
|
__entry->sum.retrans_timeo ? " rTxTo" : "")
|
|
|
|
|
);
|
|
|
|
|
|
2017-01-05 18:38:34 +08:00
|
|
|
TRACE_EVENT(rxrpc_disconnect_call,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2017-01-05 18:38:34 +08:00
|
|
|
__field(u32, abort_code )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2017-01-05 18:38:34 +08:00
|
|
|
__entry->abort_code = call->abort_code;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x ab=%08x",
|
2017-01-05 18:38:34 +08:00
|
|
|
__entry->call,
|
|
|
|
|
__entry->abort_code)
|
|
|
|
|
);
|
|
|
|
|
|
|
|
|
|
TRACE_EVENT(rxrpc_improper_term,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2017-01-05 18:38:34 +08:00
|
|
|
__field(u32, abort_code )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2017-01-05 18:38:34 +08:00
|
|
|
__entry->abort_code = call->abort_code;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x ab=%08x",
|
2017-01-05 18:38:34 +08:00
|
|
|
__entry->call,
|
|
|
|
|
__entry->abort_code)
|
|
|
|
|
);
|
|
|
|
|
|
2017-04-06 17:12:00 +08:00
|
|
|
TRACE_EVENT(rxrpc_rx_eproto,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call, rxrpc_serial_t serial,
|
|
|
|
|
const char *why),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call, serial, why),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2017-04-06 17:12:00 +08:00
|
|
|
__field(rxrpc_serial_t, serial )
|
|
|
|
|
__field(const char *, why )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2017-04-06 17:12:00 +08:00
|
|
|
__entry->serial = serial;
|
|
|
|
|
__entry->why = why;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x EPROTO %08x %s",
|
2017-04-06 17:12:00 +08:00
|
|
|
__entry->call,
|
|
|
|
|
__entry->serial,
|
|
|
|
|
__entry->why)
|
|
|
|
|
);
|
|
|
|
|
|
2017-04-06 17:12:00 +08:00
|
|
|
TRACE_EVENT(rxrpc_connect_call,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2017-04-06 17:12:00 +08:00
|
|
|
__field(unsigned long, user_call_ID )
|
|
|
|
|
__field(u32, cid )
|
|
|
|
|
__field(u32, call_id )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2017-04-06 17:12:00 +08:00
|
|
|
__entry->user_call_ID = call->user_call_ID;
|
|
|
|
|
__entry->cid = call->cid;
|
|
|
|
|
__entry->call_id = call->call_id;
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x u=%p %08x:%08x",
|
2017-04-06 17:12:00 +08:00
|
|
|
__entry->call,
|
|
|
|
|
(void *)__entry->user_call_ID,
|
|
|
|
|
__entry->cid,
|
|
|
|
|
__entry->call_id)
|
|
|
|
|
);
|
|
|
|
|
|
2018-03-28 06:02:47 +08:00
|
|
|
TRACE_EVENT(rxrpc_resend,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call, int ix),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call, ix),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
2018-03-28 06:03:00 +08:00
|
|
|
__field(unsigned int, call )
|
2018-03-28 06:02:47 +08:00
|
|
|
__field(int, ix )
|
|
|
|
|
__array(u8, anno, 64 )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
2018-03-28 06:03:00 +08:00
|
|
|
__entry->call = call->debug_id;
|
2018-03-28 06:02:47 +08:00
|
|
|
__entry->ix = ix;
|
|
|
|
|
memcpy(__entry->anno, call->rxtx_annotations, 64);
|
|
|
|
|
),
|
|
|
|
|
|
2018-03-28 06:03:00 +08:00
|
|
|
TP_printk("c=%08x ix=%u a=%64phN",
|
2018-03-28 06:02:47 +08:00
|
|
|
__entry->call,
|
|
|
|
|
__entry->ix,
|
|
|
|
|
__entry->anno)
|
|
|
|
|
);
|
|
|
|
|
|
2018-05-11 06:26:01 +08:00
|
|
|
TRACE_EVENT(rxrpc_rx_icmp,
|
|
|
|
|
TP_PROTO(struct rxrpc_peer *peer, struct sock_extended_err *ee,
|
|
|
|
|
struct sockaddr_rxrpc *srx),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(peer, ee, srx),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
|
|
|
|
__field(unsigned int, peer )
|
|
|
|
|
__field_struct(struct sock_extended_err, ee )
|
|
|
|
|
__field_struct(struct sockaddr_rxrpc, srx )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
|
|
|
|
__entry->peer = peer->debug_id;
|
|
|
|
|
memcpy(&__entry->ee, ee, sizeof(__entry->ee));
|
|
|
|
|
memcpy(&__entry->srx, srx, sizeof(__entry->srx));
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_printk("P=%08x o=%u t=%u c=%u i=%u d=%u e=%d %pISp",
|
|
|
|
|
__entry->peer,
|
|
|
|
|
__entry->ee.ee_origin,
|
|
|
|
|
__entry->ee.ee_type,
|
|
|
|
|
__entry->ee.ee_code,
|
|
|
|
|
__entry->ee.ee_info,
|
|
|
|
|
__entry->ee.ee_data,
|
|
|
|
|
__entry->ee.ee_errno,
|
|
|
|
|
&__entry->srx.transport)
|
|
|
|
|
);
|
|
|
|
|
|
2018-05-11 06:26:01 +08:00
|
|
|
TRACE_EVENT(rxrpc_tx_fail,
|
|
|
|
|
TP_PROTO(unsigned int debug_id, rxrpc_serial_t serial, int ret,
|
2018-07-24 00:18:37 +08:00
|
|
|
enum rxrpc_tx_point where),
|
2018-05-11 06:26:01 +08:00
|
|
|
|
2018-07-24 00:18:37 +08:00
|
|
|
TP_ARGS(debug_id, serial, ret, where),
|
2018-05-11 06:26:01 +08:00
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
|
|
|
|
__field(unsigned int, debug_id )
|
|
|
|
|
__field(rxrpc_serial_t, serial )
|
|
|
|
|
__field(int, ret )
|
2018-07-24 00:18:37 +08:00
|
|
|
__field(enum rxrpc_tx_point, where )
|
2018-05-11 06:26:01 +08:00
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
|
|
|
|
__entry->debug_id = debug_id;
|
|
|
|
|
__entry->serial = serial;
|
|
|
|
|
__entry->ret = ret;
|
2018-07-24 00:18:37 +08:00
|
|
|
__entry->where = where;
|
2018-05-11 06:26:01 +08:00
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_printk("c=%08x r=%x ret=%d %s",
|
|
|
|
|
__entry->debug_id,
|
|
|
|
|
__entry->serial,
|
|
|
|
|
__entry->ret,
|
2018-07-24 00:18:37 +08:00
|
|
|
__print_symbolic(__entry->where, rxrpc_tx_points))
|
2018-05-11 06:26:01 +08:00
|
|
|
);
|
|
|
|
|
|
rxrpc: Fix handling of call quietly cancelled out on server
Sometimes an in-progress call will stop responding on the fileserver when
the fileserver quietly cancels the call with an internally marked abort
(RX_CALL_DEAD), without sending an ABORT to the client.
This causes the client's call to eventually expire from lack of incoming
packets directed its way, which currently leads to it being cancelled
locally with ETIME. Note that it's not currently clear as to why this
happens as it's really hard to reproduce.
The rotation policy implement by kAFS, however, doesn't differentiate
between ETIME meaning we didn't get any response from the server and ETIME
meaning the call got cancelled mid-flow. The latter leads to an oops when
fetching data as the rotation partially resets the afs_read descriptor,
which can result in a cleared page pointer being dereferenced because that
page has already been filled.
Handle this by the following means:
(1) Set a flag on a call when we receive a packet for it.
(2) Store the highest packet serial number so far received for a call
(bearing in mind this may wrap).
(3) If, when the "not received anything recently" timeout expires on a
call, we've received at least one packet for a call and the connection
as a whole has received packets more recently than that call, then
cancel the call locally with ECONNRESET rather than ETIME.
This indicates that the call was definitely in progress on the server.
(4) In kAFS, if the rotation algorithm sees ECONNRESET rather than ETIME,
don't try the next server, but rather abort the call.
This avoids the oops as we don't try to reuse the afs_read struct.
Rather, as-yet ungotten pages will be reread at a later data.
Also:
(5) Add an rxrpc tracepoint to log detection of the call being reset.
Without this, I occasionally see an oops like the following:
general protection fault: 0000 [#1] SMP PTI
...
RIP: 0010:_copy_to_iter+0x204/0x310
RSP: 0018:ffff8800cae0f828 EFLAGS: 00010206
RAX: 0000000000000560 RBX: 0000000000000560 RCX: 0000000000000560
RDX: ffff8800cae0f968 RSI: ffff8800d58b3312 RDI: 0005080000000000
RBP: ffff8800cae0f968 R08: 0000000000000560 R09: ffff8800ca00f400
R10: ffff8800c36f28d4 R11: 00000000000008c4 R12: ffff8800cae0f958
R13: 0000000000000560 R14: ffff8800d58b3312 R15: 0000000000000560
FS: 00007fdaef108080(0000) GS:ffff8800ca680000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fb28a8fa000 CR3: 00000000d2a76002 CR4: 00000000001606e0
Call Trace:
skb_copy_datagram_iter+0x14e/0x289
rxrpc_recvmsg_data.isra.0+0x6f3/0xf68
? trace_buffer_unlock_commit_regs+0x4f/0x89
rxrpc_kernel_recv_data+0x149/0x421
afs_extract_data+0x1e0/0x798
? afs_wait_for_call_to_complete+0xc9/0x52e
afs_deliver_fs_fetch_data+0x33a/0x5ab
afs_deliver_to_call+0x1ee/0x5e0
? afs_wait_for_call_to_complete+0xc9/0x52e
afs_wait_for_call_to_complete+0x12b/0x52e
? wake_up_q+0x54/0x54
afs_make_call+0x287/0x462
? afs_fs_fetch_data+0x3e6/0x3ed
? rcu_read_lock_sched_held+0x5d/0x63
afs_fs_fetch_data+0x3e6/0x3ed
afs_fetch_data+0xbb/0x14a
afs_readpages+0x317/0x40d
__do_page_cache_readahead+0x203/0x2ba
? ondemand_readahead+0x3a7/0x3c1
ondemand_readahead+0x3a7/0x3c1
generic_file_buffered_read+0x18b/0x62f
__vfs_read+0xdb/0xfe
vfs_read+0xb2/0x137
ksys_read+0x50/0x8c
do_syscall_64+0x7d/0x1a0
entry_SYSCALL_64_after_hwframe+0x49/0xbe
Note the weird value in RDI which is a result of trying to kmap() a NULL
page pointer.
Signed-off-by: David Howells <dhowells@redhat.com>
Signed-off-by: David S. Miller <davem@davemloft.net>
2018-06-03 09:17:39 +08:00
|
|
|
TRACE_EVENT(rxrpc_call_reset,
|
|
|
|
|
TP_PROTO(struct rxrpc_call *call),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(call),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
|
|
|
|
__field(unsigned int, debug_id )
|
|
|
|
|
__field(u32, cid )
|
|
|
|
|
__field(u32, call_id )
|
|
|
|
|
__field(rxrpc_serial_t, call_serial )
|
|
|
|
|
__field(rxrpc_serial_t, conn_serial )
|
|
|
|
|
__field(rxrpc_seq_t, tx_seq )
|
|
|
|
|
__field(rxrpc_seq_t, rx_seq )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
|
|
|
|
__entry->debug_id = call->debug_id;
|
|
|
|
|
__entry->cid = call->cid;
|
|
|
|
|
__entry->call_id = call->call_id;
|
|
|
|
|
__entry->call_serial = call->rx_serial;
|
|
|
|
|
__entry->conn_serial = call->conn->hi_serial;
|
|
|
|
|
__entry->tx_seq = call->tx_hard_ack;
|
|
|
|
|
__entry->rx_seq = call->ackr_seen;
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_printk("c=%08x %08x:%08x r=%08x/%08x tx=%08x rx=%08x",
|
|
|
|
|
__entry->debug_id,
|
|
|
|
|
__entry->cid, __entry->call_id,
|
|
|
|
|
__entry->call_serial, __entry->conn_serial,
|
|
|
|
|
__entry->tx_seq, __entry->rx_seq)
|
|
|
|
|
);
|
|
|
|
|
|
2018-07-24 00:18:37 +08:00
|
|
|
TRACE_EVENT(rxrpc_notify_socket,
|
|
|
|
|
TP_PROTO(unsigned int debug_id, rxrpc_serial_t serial),
|
|
|
|
|
|
|
|
|
|
TP_ARGS(debug_id, serial),
|
|
|
|
|
|
|
|
|
|
TP_STRUCT__entry(
|
|
|
|
|
__field(unsigned int, debug_id )
|
|
|
|
|
__field(rxrpc_serial_t, serial )
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_fast_assign(
|
|
|
|
|
__entry->debug_id = debug_id;
|
|
|
|
|
__entry->serial = serial;
|
|
|
|
|
),
|
|
|
|
|
|
|
|
|
|
TP_printk("c=%08x r=%08x",
|
|
|
|
|
__entry->debug_id,
|
|
|
|
|
__entry->serial)
|
|
|
|
|
);
|
|
|
|
|
|
2016-08-23 22:27:24 +08:00
|
|
|
#endif /* _TRACE_RXRPC_H */
|
|
|
|
|
|
|
|
|
|
/* This part must be outside protection */
|
|
|
|
|
#include <trace/define_trace.h>
|