Re: [PATCH] net/tcp: introduce TRACE_EVENT for TCP/IPv4 state transition

[Song Liu]

> On Nov 9, 2017, at 10:34 AM, Song Liu <songliubraving@xxxxxx> wrote:
> 
>> 
>> On Nov 9, 2017, at 10:18 AM, Steven Rostedt <rostedt@xxxxxxxxxxx> wrote:
>> 
>> On Thu, 9 Nov 2017 15:43:29 +0900
>> Alexei Starovoitov <alexei.starovoitov@xxxxxxxxx> wrote:
>> 
>>>> +TRACE_EVENT(tcp_set_state,
>>>> +	TP_PROTO(struct sock *sk, int oldstate, int newstate),
>>>> +	TP_ARGS(sk, oldstate, newstate),
>>>> +
>>>> +	TP_STRUCT__entry(
>>>> +		__field(__be32, dst)
>>>> +		__field(__be32, src)
>>>> +		__field(__u16, dport)
>>>> +		__field(__u16, sport)
>>>> +		__field(int, oldstate)
>>>> +		__field(int, newstate)
>>>> +	),
>>>> +
>>>> +	TP_fast_assign(
>>>> +		if (oldstate == TCP_TIME_WAIT) {
>>>> +			__entry->dst = inet_twsk(sk)->tw_daddr;
>>>> +			__entry->src = inet_twsk(sk)->tw_rcv_saddr;
>>>> +			__entry->dport = ntohs(inet_twsk(sk)->tw_dport);
>>>> +			__entry->sport = ntohs(inet_twsk(sk)->tw_sport);
>>>> +		} else if (oldstate == TCP_NEW_SYN_RECV) {
>>>> +			__entry->dst = inet_rsk(inet_reqsk(sk))->ir_rmt_addr;
>>>> +			__entry->src = inet_rsk(inet_reqsk(sk))->ir_loc_addr;
>>>> +			__entry->dport =
>>>> +				ntohs(inet_rsk(inet_reqsk(sk))->ir_rmt_port);
>>>> +			__entry->sport = inet_rsk(inet_reqsk(sk))->ir_num;
>>>> +		} else {
>>>> +			__entry->dst = inet_sk(sk)->inet_daddr;
>>>> +			__entry->src = inet_sk(sk)->inet_rcv_saddr;
>>>> +			__entry->dport = ntohs(inet_sk(sk)->inet_dport);
>>>> +			__entry->sport = ntohs(inet_sk(sk)->inet_sport);
>>>> +		}
>>>> +
>>>> +		__entry->oldstate = oldstate;
>>>> +		__entry->newstate = newstate;
>>>> +	),
>>>> +
>>>> +	TP_printk("%08X:%04X %08X:%04X, %02x %02x",
>>>> +		__entry->src, __entry->sport, __entry->dst, __entry->dport,
>>>> +		__entry->oldstate, __entry->newstate)  
>>> 
>>> direct %x of state is not allowed.
>>> This has to use show_tcp_state_name() like it's done in trace_tcp_set_state
>> 
>> Hmm, I need to look at trace_tcp_set_state. I'm guessing it is in
>> net-next too?
> 
> Yes, in net-next. There are 6 tracepoints under tcp group:
> 
>  tcp_destroy_sock  
>  tcp_receive_reset  
>  tcp_retransmit_skb  
>  tcp_retransmit_synack  
>  tcp_send_reset  
>  tcp_set_state
> 
> They are all added recently.
> 
>> 
>>> 
>>> Also I'm missing the reason to introduce another tracepoint
>>> that looks just like trace_tcp_set_state.
>> 
>> I want to make sure that perf and trace-cmd can parse the TP_printk(),
>> if it is having helper functions like that in the TP_printk() part,
>> then the libtraceevent needs to be aware of that.
>> 
> 
> tcp_set_state uses __print_symbolic to show state in text format. I found
> trace-cmd cannot parse that part:
> 
> [011] 147338.660560: tcp_set_state:        sport=16262 dport=48346 \
>    saddr=127.0.0.6 daddr=127.0.0.6 saddrv6=2401:db00:30:317e:face:0:1f:0 \
>    daddrv6=2401:db00:30:31e5:face:0:7f:0 oldstate= newstate=
> 
> Other parts of the output looks good to me.
> 
> Thanks,
> Song

I am not sure whether this is the best approach, but the following patch 
fixes the output of perf:

     0.44%  sport=16262 dport=39362 saddr=127.0.0.6 daddr=127.0.0.6 \
saddrv6=2401:db00:30:317e:face:0:1f:0 daddrv6=2401:db00:30:31e5:face:0:7f:0 \
oldstate=TCP_CLOSE_WAIT newstate=TCP_LAST_ACK

Thanks,
Song