All of lore.kernel.org
 help / color / mirror / Atom feed
* How to resolve "Waited 2000ms for CONNECT" in system resuming?
@ 2017-02-08  6:24 Yoshihiro Shimoda
  2017-02-08 15:38 ` Alan Stern
  0 siblings, 1 reply; 9+ messages in thread
From: Yoshihiro Shimoda @ 2017-02-08  6:24 UTC (permalink / raw)
  To: linux-usb; +Cc: linux-renesas-soc

Hi,

In my environment, it causes the following message during system resume if debug messages are enabled:

	usb 2-1: Waited 2000ms for CONNECT

< My environment >
 - EHCI/OHCI controllers on R-Car H3 (arch/arm64/boot/dts/renesas/r8a7795-salvator-x.dts)
 - Greg's usb.git / next branch (c95a9f83711bf53faeb4ed9bbb63a3f065613dfb) + some dts patches for R-Car H3
 - A USB 1.1 (full speed) device (A USB1.1 hub is easy to reproduce)

< Details >
- I investigated this issue and I found the issue is related the workqueue of drivers/usb/core/hub.c.
  If I modified the flags from WQ_FREEZABLE to "0", the issue disappeared.

	/*
	 * The workqueue needs to be freezable to avoid interfering with
	 * USB-PERSIST port handover. Otherwise it might see that a full-speed
	 * device was gone before the EHCI controller had handed its port
	 * over to the companion full-speed controller.
	 */
	hub_wq = alloc_workqueue("usb_hub_wq", WQ_FREEZABLE, 0);

- IIUC, an EHCI connects a full speed device first. After bus reset, an OHCI can connect the device.
  However, if WQ_FREEZABLE is set, the hub driver cannot issue bus reset while system resuming,
  and then the issue happened.

- I also found another option about "persist" feature on sysfs. If a USB1.1 device (exclude a hub) is connected,
  we can disable the feature via sysfs and then the issue also disappeared.

< Question >
How to resolve the issue?
 - Can we modified the flags of the hub's workqueue?
 - Should we disable the persist feature if we need to avoid the wait in system resume?
 - Or, other ideas?

FYI, a kernel log is copied in the end of this email when the issue happened.

Best regards,
Yoshihiro Shimoda

---
NOTICE:  BL2: R-Car Gen3 Initial Program Loader(CA57) Rev.1.0.12
NOTICE:  BL2: PRR is R-Car H3 ES1.1
NOTICE:  BL2: Boot device is HyperFlash(80MHz)
NOTICE:  BL2: LCM state is CM
NOTICE:  BL2: AVS setting succeeded. DVFS_SetVID=0x52
NOTICE:  BL2: DDR1600(rev.0.20)[COLD_BOOT]..0
NOTICE:  BL2: DRAM Split is 4ch
NOTICE:  BL2: QoS is default setting(rev.0.33)
NOTICE:  BL2: v1.3(release):c040be5
NOTICE:  BL2: Built : 16:03:29, Jan 30 2017
NOTICE:  BL2: Normal boot
NOTICE:  BL2: dst=0xe6317190 src=0x8180000 len=512(0x200)
NOTICE:  BL2: dst=0x43f00000 src=0x8180400 len=6144(0x1800)
NOTICE:  BL2: dst=0x44000000 src=0x81c0000 len=65536(0x10000)
NOTICE:  BL2: dst=0x44100000 src=0x8200000 len=524288(0x80000)
NOTICE:  BL2: dst=0x50000000 src=0x8640000 len=1048576(0x100000)


U-Boot 2015.04 (Jan 30 2017 - 16:03:32)

CPU: Renesas Electronics R8A7795 rev 1.1
Board: Salvator-X
I2C:   ready
DRAM:  3.9 GiB
MMC:   sh-sdhi: 0, sh-sdhi: 1, sh-sdhi: 2
In:    serial
Out:   serial
Err:   serial
Net:   ravb
Hit any key to stop autoboot:  3     2     1     0 
ravb Waiting for PHY auto negotiation to complete.. done
ravb: 100Base/Full
BOOTP broadcast 1
BOOTP broadcast 2
BOOTP broadcast 3
DHCP client bound to address 192.168.44.124 (1314 ms)
Using ravb device
TFTP from server 192.168.44.74; our IP address is 192.168.44.124
Filename '/salvator-x/r8a7795-salvator-x.dtb'.
Load address: 0x48000000
Loading: * ###
	 1.9 MiB/s
done
Bytes transferred = 35769 (8bb9 hex)
ravb:0 is connected to ravb.  Reconnecting to ravb
ravb Waiting for PHY auto negotiation to complete.. done
ravb: 100Base/Full
Using ravb device
TFTP from server 192.168.44.74; our IP address is 192.168.44.124
Filename '/salvator-x/Image'.
Load address: 0x48080000
Loading: * #################################################################
	 #################################################################
	 #################################################################
	 #################################################################
	 #################################################################
	 #################################################################
	 #################################################################
	 #################################################################
	 #################################################################
	 #################################################################
	 #################################################################
	 #################################################################
	 ###########################################################
	 1.1 MiB/s
done
Bytes transferred = 12311040 (bbda00 hex)
## Flattened Device Tree blob at 48000000
   Booting using the fdt blob at 0x48000000
   Using Device Tree in place at 0000000048000000, end 000000004800bbb8

Starting kernel ...

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.9.0-rc5-00059-g9f5d196-dirty (shimoda@shimoda-i7-pc) (gcc version 5.2.1 20151005 (Linaro GCC 5.2-2015.11-1) ) #45 SMP PREEMPT Wed Feb 8 14:23:47 JST 2017
[    0.000000] Boot CPU: AArch64 Processor [411fd073]
[    0.000000] debug: ignoring loglevel setting.
[    0.000000] efi: Getting EFI parameters from FDT:
[    0.000000] efi: UEFI not found.
[    0.000000] cma: Reserved 16 MiB at 0x000000007f000000
[    0.000000] On node 0 totalpages: 1015808
[    0.000000]   DMA zone: 3584 pages used for memmap
[    0.000000]   DMA zone: 0 pages reserved
[    0.000000]   DMA zone: 229376 pages, LIFO batch:31
[    0.000000]   Normal zone: 12288 pages used for memmap
[    0.000000]   Normal zone: 786432 pages, LIFO batch:31
[    0.000000] psci: probing for conduit method from DT.
[    0.000000] psci: PSCIv1.0 detected in firmware.
[    0.000000] psci: Using standard PSCI v0.2 function IDs
[    0.000000] psci: Trusted OS migration not required
[    0.000000] percpu: Embedded 21 pages/cpu @ffff8006fff72000 s48000 r8192 d29824 u86016
[    0.000000] pcpu-alloc: s48000 r8192 d29824 u86016 alloc=21*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Detected PIPT I-cache on CPU0
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 999936
[    0.000000] Kernel command line: console=ttySC0,115200 ignore_loglevel consoleblank=0 rw root=/dev/nfs ip=dhcp
[    0.000000] log_buf_len individual max cpu contribution: 4096 bytes
[    0.000000] log_buf_len total cpu_extra contributions: 12288 bytes
[    0.000000] log_buf_len min size: 16384 bytes
[    0.000000] log_buf_len: 32768 bytes
[    0.000000] early log buf free: 14668(89%)
[    0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[    0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes)
[    0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
[    0.000000] software IO TLB [mem 0x7afff000-0x7efff000] (64MB) mapped at [ffff80003afff000-ffff80003effefff]
[    0.000000] Memory: 3896224K/4063232K available (7932K kernel code, 502K rwdata, 2964K rodata, 576K init, 278K bss, 150624K reserved, 16384K cma-reserved)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     modules : 0xffff000000000000 - 0xffff000008000000   (   128 MB)
[    0.000000]     vmalloc : 0xffff000008000000 - 0xffff7dffbfff0000   (129022 GB)
[    0.000000]       .text : 0xffff000008080000 - 0xffff000008840000   (  7936 KB)
[    0.000000]     .rodata : 0xffff000008840000 - 0xffff000008b30000   (  3008 KB)
[    0.000000]       .init : 0xffff000008b30000 - 0xffff000008bc0000   (   576 KB)
[    0.000000]       .data : 0xffff000008bc0000 - 0xffff000008c3da00   (   503 KB)
[    0.000000]        .bss : 0xffff000008c3da00 - 0xffff000008c834c0   (   279 KB)
[    0.000000]     fixed   : 0xffff7dfffe7fd000 - 0xffff7dfffec00000   (  4108 KB)
[    0.000000]     PCI I/O : 0xffff7dfffee00000 - 0xffff7dffffe00000   (    16 MB)
[    0.000000]     vmemmap : 0xffff7e0000000000 - 0xffff800000000000   (  2048 GB maximum)
[    0.000000]               0xffff7e0000200000 - 0xffff7e001c000000   (   446 MB actual)
[    0.000000]     memory  : 0xffff800008000000 - 0xffff800700000000   ( 28544 MB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] Preemptible hierarchical RCU implementation.
[    0.000000] 	Build-time adjustment of leaf fanout to 64.
[    0.000000] 	RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=4.
[    0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=4
[    0.000000] NR_IRQS:64 nr_irqs:64 0
[    0.000000] arm_arch_timer: Architected cp15 timer(s) running at 8.33MHz (virt).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x1ec02923e, max_idle_ns: 440795202125 ns
[    0.000003] sched_clock: 56 bits at 8MHz, resolution 120ns, wraps every 2199023255496ns
[    0.000160] Console: colour dummy device 80x25
[    0.000177] Calibrating delay loop (skipped), value calculated using timer frequency.. 16.66 BogoMIPS (lpj=33333)
[    0.000184] pid_max: default: 32768 minimum: 301
[    0.000227] Security Framework initialized
[    0.000254] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes)
[    0.000259] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes)
[    0.000936] ASID allocator initialised with 65536 entries
[    0.032602] EFI services will not be available.
[    0.080173] Detected PIPT I-cache on CPU1
[    0.080212] CPU1: Booted secondary processor [411fd073]
[    0.112182] Detected PIPT I-cache on CPU2
[    0.112200] CPU2: Booted secondary processor [411fd073]
[    0.144212] Detected PIPT I-cache on CPU3
[    0.144228] CPU3: Booted secondary processor [411fd073]
[    0.144265] Brought up 4 CPUs
[    0.144278] SMP: Total of 4 processors activated.
[    0.144284] CPU features: detected feature: 32-bit EL0 Support
[    0.144320] CPU: All CPU(s) started at EL1
[    0.144955] devtmpfs: initialized
[    0.148522] DMI not present or invalid.
[    0.148665] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.148947] pinctrl core: initialized pinctrl subsystem
[    0.149739] NET: Registered protocol family 16
[    0.160167] cpuidle: using governor menu
[    0.160382] vdso: 2 pages (1 code @ ffff000008847000, 1 data @ ffff000008bc4000)
[    0.160396] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[    0.160866] DMA: preallocated 256 KiB pool for atomic allocations
[    0.160914] Serial: AMBA PL011 UART driver
[    0.163268] sh-pfc e6060000.pfc: r8a77950_pfc support registered
[    0.163502] renesas_irqc e61c0000.interrupt-controller: failed to add to PM domain always-on: -517
[    0.196884] HugeTLB registered 2 MB page size, pre-allocated 0 pages
[    0.197451] ACPI: Interpreter disabled.
[    0.199338] vgaarb: loaded
[    0.199504] SCSI subsystem initialized
[    0.199609] libata version 3.00 loaded.
[    0.199785] usbcore: registered new interface driver usbfs
[    0.199814] usbcore: registered new interface driver hub
[    0.199855] usbcore: registered new device driver usb
[    0.200323] i2c-sh_mobile e60b0000.i2c: I2C adapter 7, bus speed 100000 Hz
[    0.200449] pps_core: LinuxPPS API ver. 1 registered
[    0.200453] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.200468] PTP clock support registered
[    0.200556] dmi: Firmware registration failed.
[    0.200626] Advanced Linux Sound Architecture Driver Initialized.
[    0.201101] clocksource: Switched to clocksource arch_sys_counter
[    0.201194] VFS: Disk quotas dquot_6.6.0
[    0.201227] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.201380] pnp: PnP ACPI: disabled
[    0.205144] NET: Registered protocol family 2
[    0.205447] TCP established hash table entries: 32768 (order: 6, 262144 bytes)
[    0.205548] TCP bind hash table entries: 32768 (order: 7, 524288 bytes)
[    0.205851] TCP: Hash tables configured (established 32768 bind 32768)
[    0.205922] UDP hash table entries: 2048 (order: 4, 65536 bytes)
[    0.205943] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes)
[    0.206069] NET: Registered protocol family 1
[    0.206301] RPC: Registered named UNIX socket transport module.
[    0.206306] RPC: Registered udp transport module.
[    0.206308] RPC: Registered tcp transport module.
[    0.206311] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.206319] PCI: CLS 0 bytes, default 128
[    0.206733] hw perfevents: enabled with armv8_cortex_a57 PMU driver, 7 counters available
[    0.206936] kvm [1]: HYP mode not available
[    0.207919] futex hash table entries: 1024 (order: 5, 131072 bytes)
[    0.207997] audit: initializing netlink subsys (disabled)
[    0.208028] audit: type=2000 audit(0.200:1): initialized
[    0.208376] workingset: timestamp_bits=46 max_order=20 bucket_order=0
[    0.213499] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.213961] NFS: Registering the id_resolver key type
[    0.213982] Key type id_resolver registered
[    0.213985] Key type id_legacy registered
[    0.213994] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.214120] 9p: Installing v9fs 9p2000 file system support
[    0.215398] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 248)
[    0.215407] io scheduler noop registered
[    0.215483] io scheduler cfq registered (default)
[    0.217625] gpio_rcar e6050000.gpio: driving 16 GPIOs
[    0.218226] gpio_rcar e6051000.gpio: driving 28 GPIOs
[    0.218619] gpio_rcar e6052000.gpio: driving 15 GPIOs
[    0.219011] gpio_rcar e6053000.gpio: driving 16 GPIOs
[    0.219445] gpio_rcar e6054000.gpio: driving 18 GPIOs
[    0.219973] gpio_rcar e6055000.gpio: driving 26 GPIOs
[    0.220581] gpio_rcar e6055400.gpio: driving 32 GPIOs
[    0.220819] gpio_rcar e6055800.gpio: driving 4 GPIOs
[    0.221387] OF: PCI: host bridge /soc/pcie@fe000000 ranges:
[    0.221412] OF: PCI:    IO 0xfe100000..0xfe1fffff -> 0x00000000
[    0.221423] OF: PCI:   MEM 0xfe200000..0xfe3fffff -> 0xfe200000
[    0.221431] OF: PCI:   MEM 0x30000000..0x37ffffff -> 0x30000000
[    0.221436] OF: PCI:   MEM 0x38000000..0x3fffffff -> 0x38000000
[    0.389108] rcar-pcie fe000000.pcie: PCIe link down
[    0.389190] OF: PCI: host bridge /soc/pcie@ee800000 ranges:
[    0.389206] OF: PCI:    IO 0xee900000..0xee9fffff -> 0x00000000
[    0.389215] OF: PCI:   MEM 0xeea00000..0xeebfffff -> 0xeea00000
[    0.389223] OF: PCI:   MEM 0xc0000000..0xc7ffffff -> 0xc0000000
[    0.389228] OF: PCI:   MEM 0xc8000000..0xcfffffff -> 0xc8000000
[    0.549103] rcar-pcie ee800000.pcie: PCIe link down
[    0.557539] xenfs: not registering filesystem on non-xen platform
[    0.559314] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
[    0.560178] SuperH (H)SCI(F) driver initialized
[    0.560577] e6e68000.serial: ttySC1 at MMIO 0xe6e68000 (irq = 134, base_baud = 0) is a scif
[    0.560902] e6e88000.serial: ttySC0 at MMIO 0xe6e88000 (irq = 135, base_baud = 0) is a scif
[    1.459064] console [ttySC0] enabled
[    1.467001] loop: module loaded
[    1.470601] hisi_sas: driver version v1.6
[    1.476038] scsi host0: sata_rcar
[    1.479533] ata1: SATA max UDMA/133 irq 138
[    1.484211] libphy: Fixed MDIO Bus: probed
[    1.488490] tun: Universal TUN/TAP device driver, 1.6
[    1.493545] tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
[    1.500235] e1000e: Intel(R) PRO/1000 Network Driver - 3.2.6-k
[    1.506070] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
[    1.512020] igb: Intel(R) Gigabit Ethernet Network Driver - version 5.4.0-k
[    1.518981] igb: Copyright (c) 2007-2014 Intel Corporation.
[    1.524582] igbvf: Intel(R) Gigabit Virtual Function Network Driver - version 2.4.0-k
[    1.532411] igbvf: Copyright (c) 2009 - 2012 Intel Corporation.
[    1.538356] sky2: driver version 1.30
[    1.542498] libphy: ravb_mii: probed
[    1.546732] ravb e6800000.ethernet eth0: Base address at 0xe6800000, 2e:09:0a:00:a3:e8, IRQ 131.
[    1.555866] VFIO - User Level meta-driver version: 0.3
[    1.561724] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.568256] ehci_hcd: block sizes: qh 144 qtd 96 itd 192 sitd 96
[    1.574261] ehci-pci: EHCI PCI platform driver
[    1.578727] ehci-platform: EHCI generic platform driver
[    1.584122] ehci-platform ee0a0100.usb: EHCI Host Controller
[    1.589796] ehci-platform ee0a0100.usb: new USB bus registered, assigned bus number 1
[    1.597721] ehci-platform ee0a0100.usb: enable per-port change event
[    1.604074] ehci-platform ee0a0100.usb: park 0
[    1.608552] ehci-platform ee0a0100.usb: irq 144, io mem 0xee0a0100
[    1.629109] ehci-platform ee0a0100.usb: USB 2.0 started, EHCI 1.10
[    1.635352] usb usb1: default language 0x0409
[    1.639736] usb usb1: udev 1, busnum 1, minor = 0
[    1.644663] usb usb1: usb_probe_device
[    1.648417] usb usb1: configuration #1 chosen from 1 choice
[    1.653993] usb usb1: usb_autoresume_device: cnt 3 -> 1
[    1.659234] usb usb1: adding 1-0:1.0 (config #1, interface 0)
[    1.665040] hub 1-0:1.0: usb_probe_interface
[    1.669311] hub 1-0:1.0: usb_probe_interface - got id
[    1.674362] usb usb1: usb_autoresume_device: cnt 6 -> 1
[    1.679587] hub 1-0:1.0: USB hub found
[    1.683346] hub 1-0:1.0: 1 port detected
[    1.687268] hub 1-0:1.0: standalone hub
[    1.691101] hub 1-0:1.0: individual port power switching
[    1.696410] hub 1-0:1.0: individual port over-current protection
[    1.702414] hub 1-0:1.0: power on to power good time: 20ms
[    1.707912] hub 1-0:1.0: local power source is good
[    1.712837] hub 1-0:1.0: enabling power on all ports
[    1.717818] usb usb1: usb_autosuspend_device: cnt 4 -> 0
[    1.723168] usb usb1: usb_autosuspend_device: cnt 1 -> 0
[    1.728590] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    1.734771] ohci_hcd: block sizes: ed 112 td 96
[    1.739309] ohci-pci: OHCI PCI platform driver
[    1.743786] ohci-platform: OHCI generic platform driver
[    1.749150] ohci-platform ee0a0000.usb: Generic Platform OHCI controller
[    1.755858] ohci-platform ee0a0000.usb: new USB bus registered, assigned bus number 2
[    1.763743] ohci-platform ee0a0000.usb: created debug files
[    1.769321] ohci-platform ee0a0000.usb: irq 144, io mem 0xee0a0000
[    1.821135] usb usb1-port1: status 0501 change 0001
[    1.863112] ohci-platform ee0a0000.usb: OHCI controller state
[    1.868858] ohci-platform ee0a0000.usb: OHCI 1.0, NO legacy support registers, rh state running
[    1.877554] ohci-platform ee0a0000.usb: control 0x083 HCFS=operational CBSR=3
[    1.884687] ohci-platform ee0a0000.usb: cmdstatus 0x00000 SOC=0
[    1.890605] ohci-platform ee0a0000.usb: intrstatus 0x00000004 SF
[    1.896609] ohci-platform ee0a0000.usb: intrenable 0x8000005a MIE RHSC UE RD WDH
[    1.897108] ata1: link resume succeeded after 1 retries
[    1.909220] ohci-platform ee0a0000.usb: hcca frame #004d
[    1.914531] ohci-platform ee0a0000.usb: roothub.a 0f000201 POTPGT=15 NPS NDP=1(1)
[    1.922011] ohci-platform ee0a0000.usb: roothub.b 00000000 PPCM=0000 DR=0000
[    1.929055] ohci-platform ee0a0000.usb: roothub.status 00008000 DRWE
[    1.935413] hub 1-0:1.0: usb_autopm_put_interface_async: cnt 1 -> 0
[    1.935417] hub 1-0:1.0: state 7 ports 1 chg 0002 evt 0000
[    1.935421] hub 1-0:1.0: usb_autopm_get_interface: cnt 2 -> 1
[    1.935435] usb usb1-port1: status 0501, change 0000, 480 Mb/s
[    1.958765] ohci-platform ee0a0000.usb: roothub.portstatus [0] 0x00000100 PPS
[    1.965926] usb usb2: default language 0x0409
[    1.970301] usb usb2: udev 1, busnum 2, minor = 128
[    1.975357] usb usb2: usb_probe_device
[    1.979110] usb usb2: configuration #1 chosen from 1 choice
[    1.984682] usb usb2: usb_autoresume_device: cnt 3 -> 1
[    1.989917] usb usb2: adding 2-0:1.0 (config #1, interface 0)
[    1.995818] ehci-platform ee0a0100.usb: port 1 full speed --> companion
[    1.995827] ohci-platform ee0a0000.usb: rhsc
[    1.995829] hub 1-0:1.0: port_wait_reset: err = -16
[    1.995831] usb usb1-port1: not enabled, trying reset again...
[    2.003284] ata1: SATA link down (SStatus 0 SControl 300)
[    2.022889] hub 2-0:1.0: usb_probe_interface
[    2.027160] hub 2-0:1.0: usb_probe_interface - got id
[    2.032210] usb usb2: usb_autoresume_device: cnt 6 -> 1
[    2.037433] hub 2-0:1.0: USB hub found
[    2.041194] hub 2-0:1.0: 1 port detected
[    2.045115] hub 2-0:1.0: standalone hub
[    2.048944] hub 2-0:1.0: no power switching (usb 1.0)
[    2.053993] hub 2-0:1.0: global over-current protection
[    2.059215] hub 2-0:1.0: power on to power good time: 30ms
[    2.064711] hub 2-0:1.0: local power source is good
[    2.069587] hub 2-0:1.0: no over-current condition exists
[    2.075018] hub 2-0:1.0: trying to enable port power on non-switchable hub
[    2.081901] usb usb2: usb_autosuspend_device: cnt 4 -> 0
[    2.087244] usb usb2: usb_autosuspend_device: cnt 1 -> 0
[    2.092910] usbcore: registered new interface driver usb-storage
[    2.099584] mousedev: PS/2 mouse device common for all mice
[    2.105426] i2c /dev entries driver
[    2.114717] cs2000-cp 2-004f: revision - C1
[    2.118926] i2c-rcar e6510000.i2c: probed
[    2.123975] sdhci: Secure Digital Host Controller Interface driver
[    2.130162] sdhci: Copyright(c) Pierre Ossman
[    2.134926] sh_mobile_sdhi ee100000.sd: Got CD GPIO
[    2.139822] sh_mobile_sdhi ee100000.sd: Got WP GPIO
[    2.144921] sh_mobile_sdhi ee160000.sd: Got CD GPIO
[    2.149817] sh_mobile_sdhi ee160000.sd: Got WP GPIO
[    2.154851] Synopsys Designware Multimedia Card Interface Driver
[    2.161074] sdhci-pltfm: SDHCI platform and OF driver helper
[    2.166897] ledtrig-cpu: registered to indicate activity on CPUs
[    2.173318] usbcore: registered new interface driver usbhid
[    2.178893] usbhid: USB HID core driver
[    2.185134] ohci-platform ee0a0000.usb: GetStatus roothub.portstatus [0] = 0x00010101 CSC PPS CCS
[    2.187797] rcar_sound ec500000.sound: probed
[    2.188043] NET: Registered protocol family 17
[    2.188103] 9pnet: Installing 9P2000 support
[    2.188153] Key type dns_resolver registered
[    2.188550] registered taskstats version 1
[    2.192803] renesas_irqc e61c0000.interrupt-controller: driving 6 irqs
[    2.194446] sh_mobile_sdhi ee100000.sd: Got CD GPIO
[    2.194464] sh_mobile_sdhi ee100000.sd: Got WP GPIO
[    2.202915] hub 1-0:1.0: usb_autopm_put_interface: cnt 1 -> 0
[    2.202921] hub 1-0:1.0: state 7 ports 1 chg 0000 evt 0002
[    2.202925] hub 1-0:1.0: usb_autopm_get_interface: cnt 2 -> 1
[    2.202944] usb usb1-port1: status 0100, change 0001, 12 Mb/s
[    2.254581] usb usb2-port1: status 0101 change 0001
[    2.321242] sh_mobile_sdhi ee100000.sd: mmc0 base at 0xee100000 max clock rate 200 MHz
[    2.329455] sh_mobile_sdhi ee160000.sd: Got CD GPIO
[    2.334353] sh_mobile_sdhi ee160000.sd: Got WP GPIO
[    2.345119] usb usb1-port1: debounce total 100ms stable 100ms status 0x100
[    2.352002] hub 1-0:1.0: usb_autopm_put_interface: cnt 0 -> 0
[    2.357752] hub 1-0:1.0: hub_suspend
[    2.361339] hub 1-0:1.0: usb_suspend_interface: status 0
[    2.366654] usb usb1: bus auto-suspend, wakeup 1
[    2.371270] ehci-platform ee0a0100.usb: suspend root hub
[    2.376618] usb usb1: usb_suspend_device: status 0
[    2.381407] usb usb1: usb_suspend_both: status 0
[    2.386030] hub 2-0:1.0: usb_autopm_put_interface_async: cnt 1 -> 0
[    2.392299] hub 2-0:1.0: state 7 ports 1 chg 0002 evt 0000
[    2.397784] hub 2-0:1.0: usb_autopm_get_interface: cnt 2 -> 1
[    2.403539] usb usb2-port1: status 0101, change 0000, 12 Mb/s
[    2.421117] ohci-platform ee0a0000.usb: rhsc
[    2.461208] sh_mobile_sdhi ee160000.sd: mmc1 base at 0xee160000 max clock rate 200 MHz
[    2.469694] asoc-simple-card sound: ak4613-hifi <-> ec500000.sound mapping ok
[    2.478556] hctosys: unable to open rtc device (rtc0)
[    2.529130] ohci-platform ee0a0000.usb: GetStatus roothub.portstatus [0] = 0x00100103 PRSC PPS PES CCS
[    2.560885] ravb e6800000.ethernet eth0: limited PHY to 100Mbit/s
[    2.566985] Micrel KSZ9031 Gigabit PHY e6800000.etherne:00: attached PHY driver [Micrel KSZ9031 Gigabit PHY] (mii_bus:phy_addr=e6800000.etherne:00, irq=223)
[    2.597113] usb 2-1: new full-speed USB device number 2 using ohci-platform
[    2.725108] ohci-platform ee0a0000.usb: GetStatus roothub.portstatus [0] = 0x00100103 PRSC PPS PES CCS
[    2.821104] usb 2-1: ep0 maxpacket = 8
[    2.832140] usb 2-1: udev 2, busnum 2, minor = 129
[    2.837170] usb 2-1: usb_probe_device
[    2.840829] usb 2-1: configuration #1 chosen from 1 choice
[    2.846317] usb 2-1: usb_autoresume_device: cnt 3 -> 1
[    2.853154] usb 2-1: adding 2-1:1.0 (config #1, interface 0)
[    2.858871] hub 2-1:1.0: usb_probe_interface
[    2.863142] hub 2-1:1.0: usb_probe_interface - got id
[    2.868192] usb 2-1: usb_autoresume_device: cnt 6 -> 1
[    2.873331] hub 2-1:1.0: USB hub found
[    2.878133] hub 2-1:1.0: 4 ports detected
[    2.882145] hub 2-1:1.0: standalone hub
[    2.885978] hub 2-1:1.0: individual port power switching
[    2.891287] hub 2-1:1.0: individual port over-current protection
[    2.897293] hub 2-1:1.0: power on to power good time: 100ms
[    2.907134] hub 2-1:1.0: local power source is good
[    2.912115] hub 2-1:1.0: enabling power on all ports
[    2.927133] usb 2-1: usb_autosuspend_device: cnt 4 -> 0
[    2.932396] usb 2-1: usb_autosuspend_device: cnt 1 -> 0
[    2.937662] hub 2-0:1.0: usb_autopm_put_interface: cnt 1 -> 0
[    2.943409] hub 2-0:1.0: state 7 ports 1 chg 0000 evt 0002
[    2.948893] hub 2-0:1.0: usb_autopm_get_interface: cnt 2 -> 1
[    2.954650] hub 2-0:1.0: usb_autopm_put_interface: cnt 0 -> 0
[    3.039139] ohci-platform ee0a0000.usb: link ed ffff000008c8a070 branch 0 [11us.], interval 32
[    3.047755] hub 2-1:1.0: usb_autopm_put_interface_async: cnt 1 -> 0
[    3.054020] hub 2-1:1.0: state 7 ports 4 chg 0000 evt 0000
[    3.059504] hub 2-1:1.0: usb_autopm_get_interface: cnt 2 -> 1
[    3.065248] hub 2-1:1.0: usb_autopm_put_interface: cnt 0 -> 0
[    3.070993] hub 2-1:1.0: hub_suspend
[    3.074571] ohci-platform ee0a0000.usb: unlink ed ffff000008c8a070 branch 0 [11us.], interval 32
[    3.084130] hub 2-1:1.0: usb_suspend_interface: status 0
[    3.091139] usb 2-1: usb auto-suspend, wakeup 1
[    3.113105] usb 2-1: usb_suspend_device: status 0
[    3.117809] usb 2-1: usb_suspend_both: status 0
[    3.122339] hub 2-0:1.0: hub_suspend
[    3.125919] hub 2-0:1.0: usb_suspend_interface: status 0
[    3.131230] usb usb2: bus auto-suspend, wakeup 1
[    3.135846] ohci-platform ee0a0000.usb: suspend root hub
[    3.141157] usb usb2: usb_suspend_device: status 0
[    3.145946] usb usb2: usb_suspend_both: status 0
[    4.156475] ravb e6800000.ethernet eth0: Link is Up - 100Mbps/Full - flow control rx/tx
[    4.185106] Sending DHCP requests .., OK
[    6.901102] IP-Config: Got DHCP answer from 192.168.44.74, my address is 192.168.44.124
[    6.909108] IP-Config: Complete:
[    6.912331]      device=eth0, hwaddr=2e:09:0a:00:a3:e8, ipaddr=192.168.44.124, mask=255.255.255.0, gw=192.168.44.74
[    6.922763]      host=192.168.44.124, domain=shimoda-i7.org, nis-domain=(none)
[    6.929981]      bootserver=192.168.44.74, rootserver=192.168.44.74, rootpath=/var/lib/tftpboot/arm_linux/rootfs/debian/armel-wheezy     nameserver0=192.168.44.74
[    6.944889] SDHI0 Vcc: disabling
[    6.948127] SDHI3 Vcc: disabling
[    6.951355] USB20_VBUS0: disabling
[    6.954756] SDHI0 VccQ: disabling
[    6.958074] SDHI3 VccQ: disabling
[    6.961388] ALSA device list:
[    6.964348]   #0: rsnd-dai.0-ak4613-hifi
[    6.971105] VFS: Mounted root (nfs filesystem) on device 0:14.
[    6.977160] devtmpfs: mounted
[    6.980462] Freeing unused kernel memory: 576K (ffff800008b30000 - ffff800008bc0000)
[    6.995361] random: fast init done
< snip >
root@192:~# ~/i2c-tools/i2cset -f -y 7 0x30 0x20 0x0f
root@192:~# ./suspend.sh 
[   23.525355] PM: Syncing filesystems ... done.
[   23.539634] Freezing user space processes ... [   23.545183] (elapsed 0.001 seconds) done.
[   23.549218] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[   23.558465] usb usb2: usb auto-resume
[   23.558705] usb usb1: usb auto-resume
[   23.558713] ehci-platform ee0a0100.usb: resume root hub
[   23.558726] usb usb1: usb_resume_device: status 0
[   23.558730] hub 1-0:1.0: hub_resume
[   23.558775] hub 1-0:1.0: usb_resume_interface: status 0
[   23.558779] usb usb1: usb_resume_both: status 0
[   23.558783] hub 1-0:1.0: hub_suspend
[   23.558806] hub 1-0:1.0: usb_suspend_interface: status 0
[   23.558810] usb usb1: bus suspend, wakeup 0
[   23.558813] ehci-platform ee0a0100.usb: suspend root hub
[   23.573226] usb usb1: usb_suspend_device: status 0
[   23.573231] usb usb1: usb_suspend_both: status 0
[   23.616710] ohci-platform ee0a0000.usb: resume root hub
[   23.697109] usb usb2: usb_resume_device: status 0
[   23.701813] hub 2-0:1.0: hub_resume
[   23.705320] usb usb2-port1: status 0107 change 0000
[   23.710203] hub 2-0:1.0: usb_resume_interface: status 0
[   23.715430] usb usb2: usb_resume_both: status 0
[   23.719975] usb 2-1: usb auto-resume
[   23.744112] ohci-platform ee0a0000.usb: rhsc
[   23.769111] ohci-platform ee0a0000.usb: GetStatus roothub.portstatus [0] = 0x00040103 PSSC PPS PES CCS
[   23.797112] usb 2-1: Waited 0ms for CONNECT
[   23.801294] usb 2-1: finish resume
[   23.809132] usb 2-1: usb_resume_device: status 0
[   23.813754] hub 2-1:1.0: hub_resume
[   23.828137] ohci-platform ee0a0000.usb: link ed ffff000008c8a070 branch 0 [11us.], interval 32
[   23.836759] hub 2-1:1.0: usb_resume_interface: status 0
[   23.841985] usb 2-1: usb_resume_both: status 0
[   23.846426] hub 2-1:1.0: hub_suspend
[   23.850003] ohci-platform ee0a0000.usb: unlink ed ffff000008c8a070 branch 0 [11us.], interval 32
[   23.859128] hub 2-1:1.0: usb_suspend_interface: status 0
[   23.864441] usb 2-1: usb suspend, wakeup 0
[   23.868535] usb 2-1: usb_suspend_device: status 0
[   23.873238] usb 2-1: usb_suspend_both: status 0
[   23.877774] hub 2-0:1.0: hub_suspend
[   23.881369] hub 2-0:1.0: usb_suspend_interface: status 0
[   23.886682] usb usb2: bus suspend, wakeup 0
[   23.890865] ohci-platform ee0a0000.usb: suspend root hub
[   23.896177] usb usb2: usb_suspend_device: status 0
[   23.900967] usb usb2: usb_suspend_both: status 0
[   23.908167] PM: suspend of devices complete after 349.792 msecs
[   23.914744] PM: late suspend of devices complete after 0.621 msecs
[   23.921585] PM: noirq suspend of devices complete after 0.653 msecs
[   23.927857] Disabling non-boot CPUs ...
[   23.953500] CPU1: shutdown
[   23.956205] psci: CPU1 killed.
[   23.993430] CPU2: shutdown
[   23.996135] psci: CPU2 killed.
[   24.033384] CPU3: shutdown
[   24.036090] psci: CPU3 killed.
NOTICE:  BL2: R-Car Gen3 Initial Program Loader(CA57) Rev.1.0.12
NOTICE:  BL2: PRR is R-Car H3 ES1.1
NOTICE:  BL2: Boot device is HyperFlash(80MHz)
NOTICE:  BL2: LCM state is CM
NOTICE:  BL2: AVS setting succeeded. DVFS_SetVID=0x52
NOTICE:  BL2: DDR1600(rev.0.20)[WARM_BOOT]..0
NOTICE:  BL2: DRAM Split is 4ch
NOTICE:  BL2: QoS is default setting(rev.0.33)
NOTICE:  BL2: v1.3(release):c040be5
NOTICE:  BL2: Built : 16:03:29, Jan 30 2017
NOTICE:  BL2: Normal boot
NOTICE:  BL2: Skip loading images. (SuspendToRAM)�[   24.049987] Enabling non-boot CPUs ...
[   24.065614] Detected PIPT I-cache on CPU1
[   24.065654] CPU1: Booted secondary processor [411fd073]
[   24.065850]  cache: parent cpu1 should not be sleeping
[   24.080354] CPU1 is up
[   24.097560] Detected PIPT I-cache on CPU2
[   24.097576] CPU2: Booted secondary processor [411fd073]
[   24.097733]  cache: parent cpu2 should not be sleeping
[   24.112180] CPU2 is up
[   24.133635] Detected PIPT I-cache on CPU3
[   24.133652] CPU3: Booted secondary processor [411fd073]
[   24.133809]  cache: parent cpu3 should not be sleeping
[   24.148268] CPU3 is up
[   24.229090] PM: noirq resume of devices complete after 78.467 msecs
[   24.235840] PM: early resume of devices complete after 0.332 msecs
[   24.316833] ravb e6800000.ethernet eth0: limited PHY to 100Mbit/s
[   24.322908] Micrel KSZ9031 Gigabit PHY e6800000.etherne:00: attached PHY driver [Micrel KSZ9031 Gigabit PHY] (mii_bus:phy_addr=e6800000.etherne:00, irq=223)
[   24.337523] usb usb1: root hub lost power or was reset
[   24.342677] ohci-platform ee0a0000.usb: lost power
[   24.342679] usb usb1: usb resume
[   24.342686] ehci-platform ee0a0100.usb: resume root hub after power loss
[   24.342701] usb usb1: usb_resume_device: status 0
[   24.342706] hub 1-0:1.0: hub_reset_resume
[   24.342711] hub 1-0:1.0: enabling power on all ports
[   24.449084] usb usb1-port1: status 0501 change 0001
[   24.459078] ohci-platform ee0a0000.usb: OHCI controller state
[   24.464828] ohci-platform ee0a0000.usb: OHCI 1.0, NO legacy support registers, rh state running
[   24.473525] ohci-platform ee0a0000.usb: control 0x083 HCFS=operational CBSR=3
[   24.480659] ohci-platform ee0a0000.usb: cmdstatus 0x00000 SOC=0
[   24.486579] ohci-platform ee0a0000.usb: intrstatus 0x00000004 SF
[   24.492585] ohci-platform ee0a0000.usb: intrenable 0x8000005a MIE RHSC UE RD WDH
[   24.499980] ohci-platform ee0a0000.usb: hcca frame #0047
[   24.505293] ohci-platform ee0a0000.usb: roothub.a 0f000201 POTPGT=15 NPS NDP=1(1)
[   24.512774] ohci-platform ee0a0000.usb: roothub.b 00000000 PPCM=0000 DR=0000
[   24.519821] ohci-platform ee0a0000.usb: roothub.status 00008000 DRWE
[   24.526175] ohci-platform ee0a0000.usb: roothub.portstatus [0] 0x00000100 PPS
[   24.533308] ohci-platform ee0a0000.usb: restart complete
[   24.538618] usb usb2: root hub lost power or was reset
[   24.543756] ohci-platform ee0a0000.usb: suspend root hub
[   24.549083] usb usb2: usb resume
[   24.549777] i2c-rcar e6510000.i2c: error -11 : f
[   24.551009] i2c-rcar e6510000.i2c: error -16 : f
[   24.551016] ak4613-codec 2-0010: Unable to sync registers 0x0-0x2. -16
[   24.561075] hub 1-0:1.0: usb_resume_interface: status 0
[   24.561079] usb usb1: usb_resume_both: status 0
[   24.577798] ohci-platform ee0a0000.usb: resume root hub
[   24.668078] usb usb2: usb_resume_device: status 0
[   24.672783] hub 2-0:1.0: hub_reset_resume
[   24.676791] hub 2-0:1.0: trying to enable port power on non-switchable hub
[   24.753072] ata1: link resume succeeded after 1 retries
[   24.789077] usb usb2-port1: status 0100 change 0000
[   24.793954] hub 2-0:1.0: usb_resume_interface: status 0
[   24.799177] usb usb2: usb_resume_both: status 0
[   24.864478] ata1: SATA link down (SStatus 0 SControl 300)
[   25.912166] ravb e6800000.ethernet eth0: Link is Up - 100Mbps/Full - flow control rx/tx
[   27.601081] usb 2-1: Waited 2000ms for CONNECT
[   27.606459] usb usb2-port1: status 0000.0100 after resume, -19
[   27.612292] usb 2-1: can't resume, status -19
[   27.616646] usb usb2-port1: logical disconnect
[   27.621096] usb 2-1: usb_resume_device: status -19
[   27.625885] usb 2-1: usb_resume_both: status -19
[   27.630530] PM: resume of devices complete after 3388.536 msecs
[   27.636920] Restarting tasks ... [   27.640250] hub 1-0:1.0: state 7 ports 1 chg 0002 evt 0000
[   27.640253] hub 2-0:1.0: state 7 ports 1 chg 0002 evt 0002
[   27.640259] hub 2-0:1.0: usb_autopm_get_interface: cnt 2 -> 1
[   27.640273] ohci-platform ee0a0000.usb: GetStatus roothub.portstatus [0] = 0x00010100 CSC PPS
[   27.640291] usb usb2-port1: status 0100, change 0001, 12 Mb/s
[   27.640295] usb 2-1: USB disconnect, device number 2
[   27.640298] usb 2-1: unregistering device
[   27.640302] usb 2-1: unregistering interface 2-1:1.0
[   27.640406] usb 2-1: usb_autoresume_device: cnt 1 -> 1
[   27.640817] usb 2-1: usb_suspend_both: status 0
[   27.640823] usb 2-1: usb_autosuspend_device: cnt 0 -> 0
[   27.640961] usb 2-1: usb_disable_device nuking all URBs
[   27.641110] usb 2-1:1.0: state 0 ports 0 chg 0000 evt 0000
[   27.641114] usb 2-1:1.0: usb_autopm_put_interface: cnt -1 -> 0
[   27.641392] done.
[   27.645928] usb 2-1: usb_resume_both: status -19
[   27.723220] hub 1-0:1.0: usb_autopm_get_interface: cnt 2 -> 1
[   27.723241] usb usb1-port1: status 0501, change 0000, 480 Mb/s
root@192:~# [   27.781244] ehci-platform ee0a0100.usb: port 1 full speed --> companion
[   27.787877] hub 1-0:1.0: port_wait_reset: err = -16
[   27.789081] ohci-platform ee0a0000.usb: GetStatus roothub.portstatus [0] = 0x00010101 CSC PPS CCS
[   27.801619] usb usb1-port1: not enabled, trying reset again...
[   27.933076] usb usb2-port1: debounce total 200ms stable 100ms status 0x101
[   28.013116] hub 1-0:1.0: usb_autopm_put_interface: cnt 0 -> 0
[   28.018868] hub 1-0:1.0: hub_suspend
[   28.022455] hub 1-0:1.0: usb_suspend_interface: status 0
[   28.027768] usb usb1: bus auto-suspend, wakeup 1
[   28.032386] ehci-platform ee0a0100.usb: suspend root hub
[   28.037714] usb usb1: suspend raced with wakeup event
[   28.042767] usb usb1: usb auto-resume
[   28.057078] ohci-platform ee0a0000.usb: GetStatus roothub.portstatus [0] = 0x00100103 PRSC PPS PES CCS
[   28.061070] ehci-platform ee0a0100.usb: resume root hub
[   28.061080] usb usb1: usb_suspend_device: status -16
[   28.061083] hub 1-0:1.0: hub_resume
[   28.137078] usb 2-1: new full-speed USB device number 3 using ohci-platform
[   28.169073] hub 1-0:1.0: usb_resume_interface: status 0
[   28.174297] usb usb1: usb_suspend_both: status -16
[   28.179091] hub 1-0:1.0: state 7 ports 1 chg 0000 evt 0000
[   28.184578] hub 1-0:1.0: usb_autopm_get_interface: cnt 2 -> 1
[   28.190326] hub 1-0:1.0: usb_autopm_put_interface: cnt 0 -> 0
[   28.196072] hub 1-0:1.0: hub_suspend
[   28.199654] hub 1-0:1.0: usb_suspend_interface: status 0
[   28.204964] usb usb1: bus auto-suspend, wakeup 1
[   28.209581] ehci-platform ee0a0100.usb: suspend root hub
[   28.214953] usb usb1: usb_suspend_device: status 0
[   28.219744] usb usb1: usb_suspend_both: status 0


^ permalink raw reply	[flat|nested] 9+ messages in thread

end of thread, other threads:[~2017-02-15  2:25 UTC | newest]

Thread overview: 9+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-02-08  6:24 How to resolve "Waited 2000ms for CONNECT" in system resuming? Yoshihiro Shimoda
2017-02-08 15:38 ` Alan Stern
2017-02-09  8:41   ` Yoshihiro Shimoda
2017-02-09 15:28     ` Alan Stern
2017-02-13  9:35       ` Yoshihiro Shimoda
2017-02-13 16:35         ` Alan Stern
2017-02-14 12:02           ` Yoshihiro Shimoda
2017-02-14 17:56             ` Alan Stern
2017-02-15  2:24               ` Yoshihiro Shimoda

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.