Received: by 2002:a25:e74b:0:0:0:0:0 with SMTP id e72csp467104ybh; Mon, 20 Jul 2020 23:02:40 -0700 (PDT) X-Google-Smtp-Source: ABdhPJyqfO3W4h4s7/1S2ZTH6HRMBJLIodetvQeYNhRhomHx+m1GBgAJjpMpaJxEJNrNPh2BhzsP X-Received: by 2002:a17:906:365a:: with SMTP id r26mr24295440ejb.52.1595311360227; Mon, 20 Jul 2020 23:02:40 -0700 (PDT) ARC-Seal: i=1; a=rsa-sha256; t=1595311360; cv=none; d=google.com; s=arc-20160816; b=daFQL4VLuIpjEbK32Jpg5CoAOslsIalJ+A8jlF7mJ2mb4yiY3OOWPVBvCxZ4WCX/CD jjEvlhRjEkn3QnS1CoudKORxRLNwg4yUGI1m4XqXP0yo4+EV0U2p/0Qy87v2C7gfdoYj PyN9BB2E4lmCH5pJ8DTjWphnyWIvLkqGv5VcmXmuwqM78BK2UYlb8kW1vN/EdBRdnjwj D+ce8kFTF7hqP56IC16xHsbrht/JOOswHqZLeQp32NIWAVmdBRxYSnyIRsbsat6xYANb ozJXBodx2HaYmKhvyhpREXmXE2tBjH9C2DXU6wLUFFOElnfYPHXVyLWhJS7lxjFj+yVm 735Q== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:sender:in-reply-to:content-disposition :mime-version:references:message-id:subject:cc:to:from:date; bh=yn+IvGYcGADoyV/li1kx8w6qqUr66L1fqMcGdqGychA=; b=IMcowXvDUHZqDjCmPbSxQ/arzya6oVGpx9X8GGoVMIDrF8ZFJEVUD1yS4ETNu8XS87 fjOr+Dj4TV4CIQAPRMGl4zHkYQBrV3TnjLx5yrWjIVt9JRcyydOzwkY47FiCB01090Oq vsKj+g/RrQm2/g5g3qodNvc4ggdXf3aUTZaZ9MusszR/OrKNLRPuj58Y1kd5d/ytUcbw fdT8M+8yaGt8Za1ItSvpDW9ixJJFMlQIfJBiEOKcniBa+LC7MrBWDtBpDj0AJY8ZX4q7 RDZB/LU//DXfgreMuH5WjmqP90tf5Q3ilIUocyLT7FvxJn9EQhrwyubvq8YFnT42vS6C nh6Q== ARC-Authentication-Results: i=1; mx.google.com; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=NONE sp=NONE dis=NONE) header.from=kernel.org Return-Path: Received: from vger.kernel.org (vger.kernel.org. [23.128.96.18]) by mx.google.com with ESMTP id r8si12193806edq.393.2020.07.20.23.02.17; Mon, 20 Jul 2020 23:02:40 -0700 (PDT) Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18; Authentication-Results: mx.google.com; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=NONE sp=NONE dis=NONE) header.from=kernel.org Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1727106AbgGUF7Y (ORCPT + 99 others); Tue, 21 Jul 2020 01:59:24 -0400 Received: from mail-wr1-f52.google.com ([209.85.221.52]:35165 "EHLO mail-wr1-f52.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726003AbgGUF7Y (ORCPT ); Tue, 21 Jul 2020 01:59:24 -0400 Received: by mail-wr1-f52.google.com with SMTP id z2so19953368wrp.2; Mon, 20 Jul 2020 22:59:22 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:date:from:to:cc:subject:message-id:references :mime-version:content-disposition:in-reply-to; bh=yn+IvGYcGADoyV/li1kx8w6qqUr66L1fqMcGdqGychA=; b=PjCbu2c5/HBDNxl2KyyhzDOM1FEPy+J+dPhQORs1T3mcHpsBcfq0LPOW2psZTS1vFS 4YzURtLV66x9Sbh0dot1vRZM5NvKRZ5rw9DDRMJLbbNWGDRCzHqzU/rnh1XCQNBMfPFb ltoOU3js1kpKQAQUXweIRmVnYpLCbME7+uo5NlzU7CkrP/Sg3H2CjT0CrxCvgfB2/x+j b4mqhbXAHuhGvepoT3UJ4jRq2nL93uAk59W/7dUrSpvNtiTaYrRIHDMl6Tt5AuKYr9px /BRdA2kqA/2yjxrqHQlH9R0eKlxxfVwbrgBNWbgYEdekfCVsFEytFEacOJeRBDbucxiW KitQ== X-Gm-Message-State: AOAM531qrRMZ6WaoANk2Ctfsb+1U/6RM/hHZIMJFSow1wZ1S9jBRS+iL ZEJw7szzpfa0OjSa8SVwTRY= X-Received: by 2002:adf:c185:: with SMTP id x5mr27196525wre.403.1595311161402; Mon, 20 Jul 2020 22:59:21 -0700 (PDT) Received: from localhost (ip-37-188-169-187.eurotel.cz. [37.188.169.187]) by smtp.gmail.com with ESMTPSA id d132sm1964546wmd.35.2020.07.20.22.59.19 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Mon, 20 Jul 2020 22:59:20 -0700 (PDT) Date: Tue, 21 Jul 2020 07:59:17 +0200 From: Michal Hocko To: Alan Stern Cc: LKML , Greg KH , linux-usb@vger.kernel.org, "Rafael J. Wysocki" Subject: Re: kworker/0:3+pm hogging CPU Message-ID: <20200721055917.GD4061@dhcp22.suse.cz> References: <20200720083956.GA4074@dhcp22.suse.cz> <20200720135857.GB1228057@rowland.harvard.edu> <20200720143213.GJ4074@dhcp22.suse.cz> <20200720151255.GE1228057@rowland.harvard.edu> <20200720163355.GA4061@dhcp22.suse.cz> <20200720173807.GJ1228057@rowland.harvard.edu> <20200720174530.GB4061@dhcp22.suse.cz> <20200720174812.GK1228057@rowland.harvard.edu> <20200720181605.GC4061@dhcp22.suse.cz> <20200720200243.GA1244989@rowland.harvard.edu> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20200720200243.GA1244989@rowland.harvard.edu> Sender: linux-kernel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Mon 20-07-20 16:02:43, Alan Stern wrote: > On Mon, Jul 20, 2020 at 08:16:05PM +0200, Michal Hocko wrote: > > On Mon 20-07-20 13:48:12, Alan Stern wrote: > > > On Mon, Jul 20, 2020 at 07:45:30PM +0200, Michal Hocko wrote: > > > > On Mon 20-07-20 13:38:07, Alan Stern wrote: > > > > > On Mon, Jul 20, 2020 at 06:33:55PM +0200, Michal Hocko wrote: > > > > > > On Mon 20-07-20 11:12:55, Alan Stern wrote: > > > > > > [...] > > > > > > > sudo echo 'module usbcore =p' >/debug/dynamic_debug/control > > > > > > > > > > > > > > Then wait long enough for some interesting messages to appear in the > > > > > > > kernel log (it should only take a few seconds if the worker thread is as > > > > > > > busy as you say) and collect the output from the dmesg command. > > > > > > > > > > > > > > To turn dynamic debugging back off when you're finished, use the same > > > > > > > command with "=p" changed to "-p". > > > > > > > > > > > > [ 95.395815] hub 2-0:1.0: state 7 ports 6 chg 0006 evt 0000 > > > > > > [ 95.395824] usb usb2-port1: status 0088, change 0000, 5.0 Gb/s > > > > > > [ 95.395838] usb usb2-port2: status 0088, change 0000, 5.0 Gb/s > > > > > > [ 95.396016] hub 2-0:1.0: hub_suspend > > > > > > [ 95.396023] usb usb2: bus auto-suspend, wakeup 1 > > > > > > [ 95.396029] usb usb2: bus suspend fail, err -16 > > > > > > > > > > Okay, that's the problem. You may get more specific information about > > > > > the suspend failure if you turn on dynamic debugging for the xhci-hcd > > > > > module (same command as above but with xhci-hcd instead of usbcore). > > > > > > > > Would that help to pinpoint the problem down? > > > > > > It might. I can't say for sure without seeing the output. > > > > echo 'module xhci-hcd =p' >/sys/kernel/debug/dynamic_debug/control > > > > doesn't yield to any output. I have tried both with and without usbcore > > debug output enabled. In the former there is no new output and for the > > later I get the same I have posted earlier. > > Sorry, my mistake. The module name needs to be "xhci_hcd" with an '_' > character, not a '-' character -- the same as what shows up in the lsmod > output. [14766.973734] xhci_hcd 0000:00:14.0: Get port status 2-1 read: 0xe000088, return 0x88 [14766.973738] xhci_hcd 0000:00:14.0: Get port status 2-2 read: 0xe000088, return 0x88 [14766.973742] xhci_hcd 0000:00:14.0: Get port status 2-3 read: 0xe0002a0, return 0x2a0 [14766.973746] xhci_hcd 0000:00:14.0: Get port status 2-4 read: 0xe0002a0, return 0x2a0 [14766.973750] xhci_hcd 0000:00:14.0: Get port status 2-5 read: 0xe0002a0, return 0x2a0 [14766.973754] xhci_hcd 0000:00:14.0: Get port status 2-6 read: 0xe0002a0, return 0x2a0 [14766.973759] xhci_hcd 0000:00:14.0: Get port status 2-1 read: 0xe000088, return 0x88 [14766.973763] xhci_hcd 0000:00:14.0: Get port status 2-2 read: 0xe000088, return 0x88 [14766.973771] xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 0 status = 0xe000088 [14766.973780] xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 1 status = 0xe000088 [14766.973789] xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 2 status = 0xe0002a0 [14766.973798] xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 3 status = 0xe0002a0 [14766.973807] xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 4 status = 0xe0002a0 [14766.973816] xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 5 status = 0xe0002a0 [14766.973830] xhci_hcd 0000:00:14.0: Bus suspend bailout, port over-current detected Repeating again and again. The last message suggests a HW problem? But why does the kernel try the same thing over and over? > You could also try collect a usbmon trace from the .../2u file. It does > seem that bus 2 is where the problem occurs. a random sample ffff8882447743c0 2551256361 S Ii:2:001:1 -115:2048 4 < ffff888040808cc0 2551256367 C Ci:2:001:0 0 4 = 88000000 ffff888040808cc0 2551256373 C Ci:2:001:0 0 4 = 88000000 ffff888040808cc0 2551256377 S Co:2:001:0 s 23 03 001b 0701 0000 0 ffff888040808cc0 2551256384 C Co:2:001:0 0 0 ffff888040808cc0 2551256432 C Co:2:001:0 0 0 ffff888040808cc0 2551256482 C Co:2:001:0 0 0 ffff888040808cc0 2551256531 C Co:2:001:0 0 0 ffff888040808cc0 2551256535 S Co:2:001:0 s 23 03 001b 0705 0000 0 ffff888040808cc0 2551256542 C Co:2:001:0 0 0 ffff888040808cc0 2551256551 C Co:2:001:0 0 0 ffff8882447743c0 2551256555 C Ii:2:001:1 -2:2048 0 ffff888040808cc0 2551256562 S Ci:2:001:0 s a3 00 0000 0001 0004 4 < ffff888040808cc0 2551256566 C Ci:2:001:0 0 4 = 88000000 ffff888040808cc0 2551256568 S Ci:2:001:0 s a3 00 0000 0002 0004 4 < ffff888040808cc0 2551256573 S Ci:2:001:0 s a3 00 0000 0003 0004 4 < ffff888040808cc0 2551256579 S Ci:2:001:0 s a3 00 0000 0004 0004 4 < ffff888040808cc0 2551256584 S Ci:2:001:0 s a3 00 0000 0005 0004 4 < ffff888040808cc0 2551256625 S Ci:2:001:0 s a3 00 0000 0006 0004 4 < ffff888040808cc0 2551256686 S Ci:2:001:0 s a3 00 0000 0001 0004 4 < ffff888040808cc0 2551256689 C Ci:2:001:0 0 4 = 88000000 ffff888040808cc0 2551256735 C Ci:2:001:0 0 4 = 88000000 ffff888040808cc0 2551256745 C Co:2:001:0 0 0 ffff888040808cc0 2551256748 S Co:2:001:0 s 23 03 001b 0702 0000 0 ffff888040808cc0 2551256755 C Co:2:001:0 0 0 ffff888040808cc0 2551256757 S Co:2:001:0 s 23 03 001b 0703 0000 0 ffff888040808cc0 2551256764 C Co:2:001:0 0 0 ffff888040808cc0 2551256802 C Co:2:001:0 0 0 ffff888040808cc0 2551256843 C Co:2:001:0 0 0 ffff888040808cc0 2551256871 C Co:2:001:0 0 0 ffff8882447743c0 2551256914 C Ii:2:001:1 -2:2048 0 ffff888040808cc0 2551256922 S Ci:2:001:0 s a3 00 0000 0001 0004 4 < ffff888040808cc0 2551256925 C Ci:2:001:0 0 4 = 88000000 ffff888040808cc0 2551256927 S Ci:2:001:0 s a3 00 0000 0002 0004 4 < ffff888040808cc0 2551256933 S Ci:2:001:0 s a3 00 0000 0003 0004 4 < ffff888040808cc0 2551256936 C Ci:2:001:0 0 4 = a0020000 ffff888040808cc0 2551256942 C Ci:2:001:0 0 4 = a0020000 ffff8882447743c0 2551257018 S Ii:2:001:1 -115:2048 4 < ffff888040808cc0 2551257070 S Ci:2:001:0 s a3 00 0000 0002 0004 4 < ffff888040808cc0 2551257106 C Co:2:001:0 0 0 ffff888040808cc0 2551257115 C Co:2:001:0 0 0 ffff888040808cc0 2551257125 C Co:2:001:0 0 0 ffff888040808cc0 2551257288 C Co:2:001:0 0 0 ffff888040808cc0 2551257290 S Co:2:001:0 s 23 03 001b 0706 0000 0 ffff888040808cc0 2551257297 C Co:2:001:0 0 0 ffff8882447743c0 2551257300 C Ii:2:001:1 -2:2048 0 ffff888040808cc0 2551257329 S Ci:2:001:0 s a3 00 0000 0001 0004 4 < ffff888040808cc0 2551257367 S Ci:2:001:0 s a3 00 0000 0002 0004 4 < ffff888040808cc0 2551257408 S Ci:2:001:0 s a3 00 0000 0004 0004 4 < ffff888040808cc0 2551257461 C Ci:2:001:0 0 4 = a0020000 ffff8882447743c0 2551257762 S Ii:2:001:1 -115:2048 4 < ffff888040808cc0 2551257815 S Co:2:001:0 s 23 03 001b 0701 0000 0 ffff888040808cc0 2551257823 C Co:2:001:0 0 0 ffff888040808cc0 2551257839 C Co:2:001:0 0 0 ffff888040808cc0 2551257877 C Co:2:001:0 0 0 ffff888040808cc0 2551257947 C Co:2:001:0 0 0 ffff888040808cc0 2551257996 S Ci:2:001:0 s a3 00 0000 0001 0004 4 < ffff888040808cc0 2551258005 S Ci:2:001:0 s a3 00 0000 0003 0004 4 < ffff888040808cc0 2551258017 C Ci:2:001:0 0 4 = a0020000 ffff888040808cc0 2551258057 S Ci:2:001:0 s a3 00 0000 0001 0004 4 < ffff888040808cc0 2551258140 C Co:2:001:0 0 0 ffff888040808cc0 2551258179 C Co:2:001:0 0 0 ffff888040808cc0 2551258257 C Co:2:001:0 0 0 ffff888040808cc0 2551258265 C Co:2:001:0 0 0 ffff888040808cc0 2551258273 C Co:2:001:0 0 0 ffff888040808cc0 2551258286 C Ci:2:001:0 0 4 = 88000000 ffff888040808cc0 2551258294 C Ci:2:001:0 0 4 = a0020000 ffff888040808cc0 2551258391 C Ci:2:001:0 0 4 = a0020000 ffff888040808cc0 2551258448 C Ci:2:001:0 0 4 = 88000000 ffff888040808cc0 2551258462 C Co:2:001:0 0 0 ffff888040808cc0 2551258470 C Co:2:001:0 0 0 ffff888040808cc0 2551258486 C Co:2:001:0 0 0 -- Michal Hocko SUSE Labs