Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Message-ID: <c2f59560-f925-8f43-f967-a8b33c9abd36@oracle.com>
Date:   Mon, 19 Sep 2022 09:48:48 -0700
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:91.0) Gecko/20100101
 Thunderbird/91.13.0
From:   Stephen Brennan <stephen.s.brennan@oracle.com>
Subject: Re: debugging rmmod failures
To:     Steve French <smfrench@gmail.com>,
        LKML <linux-kernel@vger.kernel.org>
Cc:     linux-fsdevel <linux-fsdevel@vger.kernel.org>
References: <CAH2r5mve4HKpPOwFuE5+r26xJ7f--M5+wC=kY0km9-T2WGak2A@mail.gmail.com>
Content-Language: en-US
In-Reply-To: <CAH2r5mve4HKpPOwFuE5+r26xJ7f--M5+wC=kY0km9-T2WGak2A@mail.gmail.com>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 7bit
MIME-Version: 1.0
X-MS-Exchange-AntiSpam-MessageData-ChunkCount: 1
X-MS-Exchange-AntiSpam-MessageData-0: =?utf-8?B?ck5oZWNkOGpneWN0NjBVTWk2ck8yejJiR0g5SnFBUGhxaXk4UVRvaEJzdHFS?=
 =?utf-8?B?NWtGOWIwbnRMaCtDRGFsN3BrTCtRUlB4NzBlaExVbnlCZDFraFQ1V1htdlJn?=
 =?utf-8?B?bTNadFpXaHlqTGVxNFRUTmZXeDFFeHplN2wrMTF0K0tkQXlWVDJTZjNWNG5Y?=
 =?utf-8?B?d3lTQlhWUUY1bi9DZThTa0dnR3IxREg1dnBSY2N6VUVmODNFL2ppb21EZnJL?=
 =?utf-8?B?Unh6eTFLQ2NMZERybWxSVHQ1b2FwQSs4bGRGRDMxK2E4ZTVlQ2xOSWcrVjdH?=
 =?utf-8?B?djR0K1Iwa2lJaFg4NlRzeTZoL0NvTy9ZK1FQOS9ZWVE4QzVvSEp0Y0h0SStB?=
 =?utf-8?B?RXArcGIyUk1TaVQwdUdLTzFVOXFYMDRnV2ttbVM1Y2FWdGltSHdiNkp3Y2pj?=
 =?utf-8?B?YUQ5U0hnZ0c0MkZCSnNoOEdQcXg3R1dCaUc5T3Q4ek1YM091ZjhNcFNyNTBq?=
 =?utf-8?B?eDVUYkJmc0ZVQ3VXSVdZR0pPVFgzWWdJemQ4TmtGSjBMZ0s3RnlObng4bTV4?=
 =?utf-8?B?MW5weUFRa0lFbkpLcm9icUtDSGtvTGR2cjhIZ1UyTmhLME01T1ZudDJ3eXdh?=
 =?utf-8?B?YXNLejhCOUFhOCtwbS9GME9YM3lZM3RhTmpWVWI5U21ETkVrUnZSZlZjMStz?=
 =?utf-8?B?RTRqbTNWU0tNUTgrcTNoeUhOR2ZxTUwwNEFrWVBoRFhLRm1uRlNSRk9qVkta?=
 =?utf-8?B?aERZSy9vaUZQbjA0Z3MvNHVzODIwNkpiZVpYUFpsWjdrMXVOd3FmVW5KSkVS?=
 =?utf-8?B?M3N2eFlUVE4vMzRYUjNuV3JUQ3lZQjhKdEN4bHptV0NXSHN3cGRBOU9EakRD?=
 =?utf-8?B?dzFOaDQ3REVaNUdNQ0dmLzFrdWx2N1ZXWGxQSThVTmFQLzlXM0hMeGdWWWNH?=
 =?utf-8?B?L0VuRlBOUk1wd1kvbHRTT0l1VGFOVEZPUFVWSGFjZWJad1JseTN6MzJXZE5P?=
 =?utf-8?B?OGlKN2lpdE5obCtmcTNybkNqb0dVYUdJTlNBTndNMDZaNHBwWHovZUg4YWUv?=
 =?utf-8?B?MGQ5QTBhOGErVFkxWHhkTVZCNEFieEJBMHZTcW5ycEwvc0ZjaEs0Z3R4akZS?=
 =?utf-8?B?UlA5L2YvL3AzSzYzTXRLc3ZxOTlEL2lwUGhxYjE1RUF2Z0pmV1QyRFRrOVll?=
 =?utf-8?B?TGwxNzhNMVJvdXNVbS9QV3pZL09UVEU0REhsdVFINi9MZWo2TzVYTFN2cERD?=
 =?utf-8?B?bWhMV3NRdjNxdnRHcXNCcXBuVDd4RDZEY0xySG0wRDJUNG1jQi83L2lkbDNX?=
 =?utf-8?B?cTd1MmVyUUgrR2Fjcll2clUzTjhlQ0lhSUxRWGNHTUZ1WWNWWkhrSGV6Vzh3?=
 =?utf-8?B?Y20wSEc4eW54MU5kaFdlanh6NGdBZklQdkxZMFY4cE5FVmVpMkE5TmhUM2R6?=
 =?utf-8?B?K1prWCtPclQ3MTcrTnlOcXB6WGdSeDh5bW9DeFRqRnFqUnlkRWVYM1pLd2dJ?=
 =?utf-8?B?ZWhMaHV6TWFNbWRBVVNRVThoc3RxQzBJRE5vUEhQZitNVUphMC9sOXhLdmJt?=
 =?utf-8?B?NVVxaC9VZGc3THVjSGdXTVZidXRvWDlUNk1teTlSU1dGZXMwMWYvaXVGTlpq?=
 =?utf-8?B?emMwa290QWdENDhNL2JYN3B3VEs4d1hVMHM2Q0hIcFo4UnAySVhJQ1Y3RFIw?=
 =?utf-8?B?ODR4ZGE1eWxtSU1XQ3ZaK3ZOVVZoWXpBRit2M2psRW92QThUQ1VJaVpSaThX?=
 =?utf-8?B?T2Y1eitBSm9SSDh3ckxPN20xcHkzL00rLzJJakt2M0NST3lRMUdmWUlLTWw4?=
 =?utf-8?B?cVlON1REVHhUYWt3eG5qTUErMWUzbmM1ZmRRSEJudWI0NWFaVDhHdlBpQjBp?=
 =?utf-8?B?cXRqVENmajA0a1oxWWNIMFZDTVhodEFUS1lLTGJ4bmRlMzFONGp1MG5ncDkz?=
 =?utf-8?B?ckJuMHFucWcrSkkrRW1BbFZtYkE1TE1BS0VqeWErcTQ4aWhvRWxYY0Zwa0t6?=
 =?utf-8?B?YlJBcitiMTBIUzF2eWxlcE1HNGFXTzBCMlROWG5GUDdQSDdmZXZ6U2Z6SWMr?=
 =?utf-8?B?cmo4TEQ0dWVlbFdvMkkyNFFJSWsvM0VUODRXNk04YlVEVlBWU2k5TkJlSkVF?=
 =?utf-8?B?UStvMmFmcUNXV1BBdFk2WXNCTlI1MkEwL21DM0p3VDJleXpOMGRpNHFOMDla?=
 =?utf-8?B?L0tiSG9mVjlLZ0EwZmY5cHhFanJrM25mNmZpdXNLLzEyOVlwaEtid010Z0hX?=
 =?utf-8?B?VFE9PQ==?=
X-OriginatorOrg: oracle.com
X-MS-Exchange-CrossTenant-Network-Message-Id: b0e52222-bd29-43f0-94f0-08da9a5ed44f
X-MS-Exchange-CrossTenant-AuthSource: CH2PR10MB4166.namprd10.prod.outlook.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-OriginalArrivalTime: 19 Sep 2022 16:48:50.7653
 (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: LeNQHwW8HnfUBWyqoUVUU1ebuItEel8di6mCXWPIs7e2ca6C9qCXkzBibSPJVRoekowGeCXMtMWdjl4jdyORjoHRC5qimOZ1wfooBbWQ+MQ=
X-MS-Exchange-Transport-CrossTenantHeadersStamped: DS0PR10MB6845
X-Proofpoint-Virus-Version: vendor=baseguard
 engine=ICAP:2.0.205,Aquarius:18.0.895,Hydra:6.0.528,FMLib:17.11.122.1
 definitions=2022-09-19_05,2022-09-16_01,2022-06-22_01
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0 mlxscore=0 phishscore=0 mlxlogscore=999
 bulkscore=0 suspectscore=0 adultscore=0 spamscore=0 malwarescore=0
 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-2209130000
 definitions=main-2209190113
X-Proofpoint-GUID: vqnPhXBV4z2V1W6lQ60Qfp5db4B4DBR2
X-Proofpoint-ORIG-GUID: vqnPhXBV4z2V1W6lQ60Qfp5db4B4DBR2
X-Spam-Status: No, score=-3.8 required=5.0 tests=BAYES_00,DKIM_SIGNED,
        DKIM_VALID,DKIM_VALID_AU,DKIM_VALID_EF,NICE_REPLY_A,RCVD_IN_DNSWL_LOW,
        RCVD_IN_MSPIKE_H2,SPF_HELO_NONE,SPF_NONE autolearn=ham
        autolearn_force=no version=3.4.6
X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on
        lindbergh.monkeyblade.net
Precedence: bulk
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

On 9/16/22 13:13, Steve French wrote:
> Any suggestions on how to debug why rmmod fails with EBUSY?
> 
> I was trying to debug a problem where rmmod fails during an xfstest
> run but couldn't find useful information on how to get ideas 'why'
> rmmod is failing (in this case with EBUSY) and I could only find two
> places where EBUSY would plausibly be returned but don't see the
> pr_debug message in the log (e.g. "already dying") that I would expect
> to get in those cases.
> 
> It also fails in this test scenario (which takes a while to reproduce
> so isn't trivial to repro) with EBUSY when doing "rmmod --verbose
> --force"  and the --verbose didn't display any additional info.
> 
> I also tried "trace-cmd record -e *module*" which showed it (one call)
> returning 0xFFFFFFF0 but nothing useful that I could see.

In situations like this I sometimes find it useful to use the ftrace
function_graph tracer. It can show you every single function call,
starting from some root function. Of course it's a bit of a footgun, so
be careful with it :)

I used it to trace the delete_module system call like so:

# trace-cmd record -p function_graph -g __x64_sys_delete_module \
                    -F rmmod $MODULE_TO_REMOVE
...
# trace-cmd report
            rmmod-41656 [007]  5506.963846: funcgraph_entry:                   |  __x64_sys_delete_module() {
            rmmod-41656 [007]  5506.963846: funcgraph_entry:                   |    capable() {
            rmmod-41656 [007]  5506.963846: funcgraph_entry:                   |      security_capable() {
...                                                                                ...
            rmmod-41656 [007]  5506.965521: funcgraph_entry:                   |    free_module() {
            rmmod-41656 [007]  5506.965521: funcgraph_entry:                   |      mod_sysfs_teardown() {
            rmmod-41656 [007]  5506.965522: funcgraph_entry:                   |        mutex_lock() {


Of course, my module teardown succeeded, but you should be able to
cross reference your function calls with the source code to see where
an error may have occurred.

Regards,
Stephen

> 
> Any ideas on how to debug *why* an rmmod fails?