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 <[email protected]>
[ 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 <[email protected]>
[ 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
