Received-SPF: pass (google.com: domain of linux-nfs-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
From:   Chuck Lever III <chuck.lever@oracle.com>
To:     Trond Myklebust <trondmy@hammerspace.com>
CC:     Anna Schumaker <anna.schumaker@netapp.com>,
        Linux NFS Mailing List <linux-nfs@vger.kernel.org>
Subject: Re: [PATCH 2/3] SUNRPC: Fix trace_xprt_transmit_queued()
Thread-Topic: [PATCH 2/3] SUNRPC: Fix trace_xprt_transmit_queued()
Thread-Index: AQHXJlKTbuswqbxABU2Pk6VPhCi4j6qeYJoAgAAZBgA=
Date:   Wed, 31 Mar 2021 19:22:06 +0000
Message-ID: <DA345B72-D2B5-44E0-83A8-CD641274BE9B@oracle.com>
References: <161721133412.515091.3634995666026759187.stgit@manet.1015granger.net>
 <161721134086.515091.16531400209127881709.stgit@manet.1015granger.net>
 <0901650f31a528a21eb6962bdc13698bfff7bd50.camel@hammerspace.com>
In-Reply-To: <0901650f31a528a21eb6962bdc13698bfff7bd50.camel@hammerspace.com>
Accept-Language: en-US
Content-Language: en-US
Content-Type: text/plain; charset="us-ascii"
Content-ID: <62C7C016EE1B424690DF6E0541BD216B@namprd10.prod.outlook.com>
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
X-MS-Exchange-CrossTenant-Network-Message-Id: 96621241-b9ad-49b5-a63d-08d8f47a45e1
X-MS-Exchange-CrossTenant-originalarrivaltime: 31 Mar 2021 19:22:06.7214
 (UTC)
X-MS-Exchange-CrossTenant-fromentityheader: Hosted
X-MS-Exchange-CrossTenant-id: 4e2c6054-71cb-48f1-bd6c-3a9705aca71b
X-MS-Exchange-CrossTenant-mailboxtype: HOSTED
X-MS-Exchange-CrossTenant-userprincipalname: DIx30PBe/qIBSQovCyQbK8C+2E8RhHgU9s+oAZI5cwG85MZwSa1EsTDEuDoVzF+ld4rukgkVlM4rA6CExhoioQ==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: SJ0PR10MB4637
X-Proofpoint-Virus-Version: vendor=nai engine=6200 definitions=9940 signatures=668683
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0 suspectscore=0 phishscore=0
 malwarescore=0 mlxlogscore=999 adultscore=0 spamscore=0 mlxscore=0
 bulkscore=0 classifier=spam adjust=0 reason=mlx scancount=1
 engine=8.12.0-2103300000 definitions=main-2103310132
X-Proofpoint-ORIG-GUID: ZZtVj1MMeuvI_HqcrYvEtiD2bXL8-dVH
X-Proofpoint-GUID: ZZtVj1MMeuvI_HqcrYvEtiD2bXL8-dVH
X-Proofpoint-Virus-Version: vendor=nai engine=6200 definitions=9940 signatures=668683
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0 impostorscore=0 priorityscore=1501
 lowpriorityscore=0 malwarescore=0 suspectscore=0 adultscore=0 mlxscore=0
 bulkscore=0 spamscore=0 clxscore=1015 mlxlogscore=999 phishscore=0
 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-2103300000
 definitions=main-2103310132
Precedence: bulk
List-ID: <linux-nfs.vger.kernel.org>
X-Mailing-List: linux-nfs@vger.kernel.org


> On Mar 31, 2021, at 1:52 PM, Trond Myklebust <trondmy@hammerspace.com> wr=
ote:
>=20
> On Wed, 2021-03-31 at 13:22 -0400, Chuck Lever wrote:
>> This tracepoint can crash when dereferencing snd_task because
>> when some transports connect, they put a cookie in that field
>> instead of a pointer to an rpc_task.
>>=20
>> BUG: KASAN: use-after-free in
>> trace_event_raw_event_xprt_writelock_event+0x141/0x18e [sunrpc]
>> Read of size 2 at addr ffff8881a83bd3a0 by task git/331872
>>=20
>> CPU: 11 PID: 331872 Comm: git Tainted: G S                5.12.0-rc2-
>> 00007-g3ab6e585a7f9 #1453
>> Hardware name: Supermicro SYS-6028R-T/X10DRi, BIOS 1.1a 10/16/2015
>> Call Trace:
>>  dump_stack+0x9c/0xcf
>>  print_address_description.constprop.0+0x18/0x239
>>  kasan_report+0x174/0x1b0
>>  trace_event_raw_event_xprt_writelock_event+0x141/0x18e [sunrpc]
>>  xprt_prepare_transmit+0x8e/0xc1 [sunrpc]
>>  call_transmit+0x4d/0xc6 [sunrpc]
>>=20
>> Fixes: 9ce07ae5eb1d ("SUNRPC: Replace dprintk() call site in
>> xprt_prepare_transmit")
>> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
>> ---
>>  include/trace/events/sunrpc.h |   35
>> ++++++++++++++++++++++++++++++++++-
>>  net/sunrpc/xprt.c             |    2 +-
>>  2 files changed, 35 insertions(+), 2 deletions(-)
>>=20
>> diff --git a/include/trace/events/sunrpc.h
>> b/include/trace/events/sunrpc.h
>> index 036eb1f5c133..690988530d60 100644
>> --- a/include/trace/events/sunrpc.h
>> +++ b/include/trace/events/sunrpc.h
>> @@ -1141,7 +1141,40 @@ DECLARE_EVENT_CLASS(xprt_writelock_event,
>> =20
>>  DEFINE_WRITELOCK_EVENT(reserve_xprt);
>>  DEFINE_WRITELOCK_EVENT(release_xprt);
>> -DEFINE_WRITELOCK_EVENT(transmit_queued);
>> +
>> +TRACE_EVENT(xprt_transmit_queued,
>> +       TP_PROTO(
>> +               const struct rpc_task *task
>> +       ),
>> +
>> +       TP_ARGS(task),
>> +
>> +       TP_STRUCT__entry(
>> +               __field(unsigned int, task_id)
>> +               __field(unsigned int, client_id)
>> +               __field(unsigned long, runstate)
>> +               __field(u32, xid)
>> +               __field(int, status)
>> +               __field(unsigned short, flags)
>> +       ),
>> +
>> +       TP_fast_assign(
>> +               __entry->task_id =3D task->tk_pid;
>> +               __entry->client_id =3D
>> +                       task->tk_client ? task->tk_client->cl_clid :
>> -1;
>> +               __entry->runstate =3D task->tk_runstate;
>> +               __entry->xid =3D be32_to_cpu(task->tk_rqstp->rq_xid);
>> +               __entry->status =3D task->tk_status;
>> +               __entry->flags =3D task->tk_flags;
>> +       ),
>> +
>> +       TP_printk("task:%u@%u xid=3D0x%08x flags=3D%s runstate=3D%s
>> status=3D%d",
>> +               __entry->task_id, __entry->client_id, __entry->xid,
>> +               rpc_show_task_flags(__entry->flags),
>> +               rpc_show_runstate(__entry->runstate),
>> +               __entry->status
>> +       )
>> +);
>> =20
>>  DECLARE_EVENT_CLASS(xprt_cong_event,
>>         TP_PROTO(
>> diff --git a/net/sunrpc/xprt.c b/net/sunrpc/xprt.c
>> index d616b93751d8..b694af4504c4 100644
>> --- a/net/sunrpc/xprt.c
>> +++ b/net/sunrpc/xprt.c
>> @@ -1469,7 +1469,7 @@ bool xprt_prepare_transmit(struct rpc_task
>> *task)
>>         struct rpc_xprt *xprt =3D req->rq_xprt;
>> =20
>>         if (!xprt_lock_write(xprt, task)) {
>> -               trace_xprt_transmit_queued(xprt, task);
>> +               trace_xprt_transmit_queued(task);
>=20
> Why do we need this tracepoint? The event we're logging is just
> "grabbing the transport write lock failed due to external
> circumstances".

This tracepoint records the decision to queue rather than send immediately.

You can count the number of these to get an idea whether the transport
is backed up.

You can trigger on this event if you want to capture the events that
lead up to queuing a request.

You can see whether the client logic is making the right choice when
congestion control is in play.


>>                 /* Race breaker: someone may have transmitted us */
>>                 if (!test_bit(RPC_TASK_NEED_XMIT, &task-
>>> tk_runstate))
>>=20
>>=20
>=20
> --=20
> Trond Myklebust
> Linux NFS client maintainer, Hammerspace
> trond.myklebust@hammerspace.com

--
Chuck Lever