lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite for Android: free password hash cracker in your pocket
[<prev] [next>] [<thread-prev] [day] [month] [year] [list]
Date:   Fri, 19 Aug 2016 14:14:27 +0300
From:   Grygorii Strashko <grygorii.strashko@...com>
To:     netdev <netdev@...r.kernel.org>,
        Trond Myklebust <trond.myklebust@...marydata.com>,
        <linux-nfs@...r.kernel.org>,
        Anna Schumaker <anna.schumaker@...app.com>
CC:     Vladimir Murzin <vladimir.murzin@....com>,
        "linux-omap@...r.kernel.org" <linux-omap@...r.kernel.org>,
        Sekhar Nori <nsekhar@...com>,
        open list <linux-kernel@...r.kernel.org>,
        linux-arm <linux-arm-kernel@...ts.infradead.org>,
        Neil Brown <neilb@...e.de>
Subject: Re: Kernel NFS boot failure

Hi All,
On 08/11/2016 07:25 PM, Grygorii Strashko wrote:
> On 08/03/2016 06:04 PM, Grygorii Strashko wrote:
>> Hi Vladimir,
>>
>> On 08/03/2016 03:06 PM, Vladimir Murzin wrote:
>>> On 03/08/16 12:41, Grygorii Strashko wrote:
>>>> We observe Kernel boot failure while running NFS boot stress test (1000 iterations):
>>>> - Linux version 4.7.0 
>>
>> I'd like to pay your attention that this issue also reproducible with
>> Kernel 4.7.0!
>> The same can be seen from the log I've provided in first e-mail:
>> [    0.000000] Linux version 4.7.0 (lcpdbld@...sdit-build06.dal.design.ti.com) (gcc version 4.9.3 20150413 (prerelease) (Linaro GCC 4.9-2015.05) ) #1 SMP Fri Jul 29 17:41:27 CDT 2016
>>
>>
>> I've not run the test with current master at it's not been tagged yet.
> 
> Still in progress. rc1 unstable on my platforms due to other issues :(
> 
>>
>>>> - am335x-evm (TI AM335x EVM)
>>>> - failure rate 10-20 times per test.
>>>> Originally this issue was reproduced using TI Kernel 4.4
>>>> ( git://git.ti.com/ti-linux-kernel/ti-linux-kernel.git, branch: ti-linux-4.4.y)
>>>> on both am335x-evm and am57xx-beagle-x15(am57xx-evm) platforms.
>>>> This issues has not been reproduced with TI Kernel 4.1 before.
>>>>
>>>> The SysRq shows that system stuck in nfs_fs_mount()
>>>>
>>>> [  207.904632] [<c07ab34c>] (schedule) from [<c0783554>] (rpc_wait_bit_killable+0x2c/0xd8)
>>>> [  207.912996] [<c0783554>] (rpc_wait_bit_killable) from [<c07ab7f0>] (__wait_on_bit+0x84/0xc0)
>>>> [  207.921812] [<c07ab7f0>] (__wait_on_bit) from [<c07ab890>] (out_of_line_wait_on_bit+0x64/0x70)
>>>> [  207.930810] [<c07ab890>] (out_of_line_wait_on_bit) from [<c07843f4>] (__rpc_execute+0x18c/0x544)
>>>> [  207.939988] [<c07843f4>] (__rpc_execute) from [<c0779f24>] (rpc_run_task+0x13c/0x158)
>>>> [  207.948166] [<c0779f24>] (rpc_run_task) from [<c0779f84>] (rpc_call_sync+0x44/0xc4)
>>>> [  207.956163] [<c0779f84>] (rpc_call_sync) from [<c077a04c>] (rpc_ping+0x48/0x68)
>>>> [  207.963796] [<c077a04c>] (rpc_ping) from [<c077a158>] (rpc_create_xprt+0xec/0x164)
>>>> [  207.971702] [<c077a158>] (rpc_create_xprt) from [<c077a2c0>] (rpc_create+0xf0/0x1a0)
>>>> [  207.979794] [<c077a2c0>] (rpc_create) from [<c0393088>] (nfs_create_rpc_client+0xd4/0xec)
>>>> [  207.988338] [<c0393088>] (nfs_create_rpc_client) from [<c0394d10>] (nfs_init_client+0x20/0x78)
>>>> [  207.997332] [<c0394d10>] (nfs_init_client) from [<c03949d4>] (nfs_create_server+0xa0/0x3bc)
>>>> [  208.006057] [<c03949d4>] (nfs_create_server) from [<c03b197c>] (nfs3_create_server+0x8/0x20)
>>>> [  208.014879] [<c03b197c>] (nfs3_create_server) from [<c03a34c4>] (nfs_try_mount+0xc4/0x1f0)
>>>> [  208.023513] [<c03a34c4>] (nfs_try_mount) from [<c03a2c48>] (nfs_fs_mount+0x290/0x910)
>>>> [  208.031702] [<c03a2c48>] (nfs_fs_mount) from [<c0294d24>] (mount_fs+0x44/0x168)
>>>>

I was able to reproduce this issue with NFS/SUNRPC debug logs enabled using TI kernel 4.4.
I'd be appreciated for any help :( and be happy to run any kind of tests or check debug patches if needed.

>From the logs I found that problem happens when rpc_task 2 is freeing too late as in the below log.
(marked as [GS])


Starting kernel ...

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Initializing cgroup subsys cpuacct
[    0.000000] Linux version 4.4.18-32575-g5db1dce (lcpdbld@...sdit-build06.dal.design.ti.com) (gcc version 4.9.3 20150413 (prerelease) (Linaro GCC 4.9-2015.05) ) #2 SMP PREEMPT Wed Aug 17 10:49:14 CDT 2016
[    0.000000] CPU: ARMv7 Processor [412fc0f2] revision 2 (ARMv7), cr=30c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
[    0.000000] Machine model: TI AM5728 EVM
[    0.000000] Reserved memory: created CMA memory pool at 0x0000000095800000, size 56 MiB
[    0.000000] Reserved memory: initialized node ipu2_cma@...00000, compatible id shared-dma-pool
[    0.000000] Reserved memory: created CMA memory pool at 0x0000000099000000, size 64 MiB
[    0.000000] Reserved memory: initialized node dsp1_cma@...00000, compatible id shared-dma-pool
[    0.000000] Reserved memory: created CMA memory pool at 0x000000009d000000, size 32 MiB
[    0.000000] Reserved memory: initialized node ipu1_cma@...00000, compatible id shared-dma-pool
[    0.000000] Reserved memory: created CMA memory pool at 0x000000009f000000, size 8 MiB
[    0.000000] Reserved memory: initialized node dsp2_cma@...00000, compatible id shared-dma-pool
[    0.000000] cma: Reserved 24 MiB at 0x00000000fe400000
[    0.000000] Forcing write-allocate cache policy for SMP
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] OMAP4: Map 0x00000000ffd00000 to fe600000 for dram barrier
[    0.000000] DRA752 ES1.1
[    0.000000] PERCPU: Embedded 11 pages/cpu @eed31000 s14848 r8192 d22016 u45056
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 521792
[    0.000000] Kernel command line: console=ttyO2,115200n8  earlyprintk=serial,ttyO2,115200n8 rootwait  ip=:::::eth0:dhcp  root=/dev/nfs rw nfsroot=192.168.0.1:/home/tigtfarm10/NFS_exports/linux/am57xx-evm/autofs/f1a395609921e4cdad1b0bb2ec56f877,nolock,v3,tcp,rsize=4096,wsize=4096 
[    0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Memory: 1875576K/2094080K available (6523K kernel code, 358K rwdata, 2408K rodata, 336K init, 289K bss, 30088K reserved, 188416K cma-reserved, 1283072K highmem)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
[    0.000000]     vmalloc : 0xf0800000 - 0xff800000   ( 240 MB)
[    0.000000]     lowmem  : 0xc0000000 - 0xf0000000   ( 768 MB)
[    0.000000]     pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
[    0.000000]     modules : 0xbf000000 - 0xbfe00000   (  14 MB)
[    0.000000]       .text : 0xc0008000 - 0xc08c106c   (8933 kB)
[    0.000000]       .init : 0xc08c2000 - 0xc0916000   ( 336 kB)
[    0.000000]       .data : 0xc0916000 - 0xc096f9a0   ( 359 kB)
[    0.000000]        .bss : 0xc0972000 - 0xc09ba6b0   ( 290 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
[    0.000000] Preemptible hierarchical RCU implementation.
[    0.000000] 	Build-time adjustment of leaf fanout to 32.
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000000] OMAP clockevent source: timer1 at 32786 Hz
[    0.000000] Architected cp15 timer(s) running at 6.14MHz (virt).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x16af5adb9, max_idle_ns: 440795202250 ns
[    0.000004] sched_clock: 56 bits at 6MHz, resolution 162ns, wraps every 4398046511023ns
[    0.000015] Switching to timer-based delay loop, resolution 162ns
[    0.000328] clocksource: 32k_counter: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 58327039986419 ns
[    0.000337] OMAP clocksource: 32k_counter at 32768 Hz
[    0.000760] Console: colour dummy device 80x30
[    0.000776] WARNING: Your 'console=ttyO2' has been replaced by 'ttyS2'
[    0.000782] This ensures that you still see kernel messages. Please
[    0.000788] update your kernel commandline.
[    0.000801] Calibrating delay loop (skipped), value calculated using timer frequency.. 12.29 BogoMIPS (lpj=61475)
[    0.000814] pid_max: default: 32768 minimum: 301
[    0.000906] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.000916] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.001461] Initializing cgroup subsys io
[    0.001478] Initializing cgroup subsys memory
[    0.001502] Initializing cgroup subsys devices
[    0.001514] Initializing cgroup subsys freezer
[    0.001525] Initializing cgroup subsys perf_event
[    0.001536] Initializing cgroup subsys pids
[    0.001562] CPU: Testing write buffer coherency: ok
[    0.001764] /cpus/cpu@0 missing clock-frequency property
[    0.001781] /cpus/cpu@1 missing clock-frequency property
[    0.001791] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.001827] Setting up static identity map for 0x800082c0 - 0x80008318
[    0.080183] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.080250] Brought up 2 CPUs
[    0.080262] SMP: Total of 2 processors activated (24.59 BogoMIPS).
[    0.080269] CPU: All CPU(s) started in SVC mode.
[    0.080643] devtmpfs: initialized
[    0.106472] VFP support v0.3: implementor 41 architecture 4 part 30 variant f rev 0
[    0.107342] omap_hwmod: l3_main_2 using broken dt data from ocp
[    0.304568] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.308002] pinctrl core: initialized pinctrl subsystem
[    0.308848] NET: Registered protocol family 16
[    0.309801] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.340242] cpuidle: using governor ladder
[    0.370275] cpuidle: using governor menu
[    0.378776] OMAP GPIO hardware version 0.1
[    0.385225] irq: no irq domain found for /ocp/l4@...00000/scm@...0/pinmux@...0 !
[    0.409647] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.409657] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.410122] omap4_sram_init:Unable to allocate sram needed to handle errata I688
[    0.410131] omap4_sram_init:Unable to get sram pool needed to handle errata I688
[    0.410723] OMAP DMA hardware revision 0.0
[    0.444520] omap-dma-engine 4a056000.dma-controller: OMAP DMA engine driver
[    0.445630] edma 43300000.edma: memcpy is disabled
[    0.450477] edma 43300000.edma: TI EDMA DMA engine driver
[    0.454327] omap-iommu 40d01000.mmu: 40d01000.mmu registered
[    0.454507] omap-iommu 40d02000.mmu: 40d02000.mmu registered
[    0.454658] omap-iommu 58882000.mmu: 58882000.mmu registered
[    0.454806] omap-iommu 55082000.mmu: 55082000.mmu registered
[    0.455061] omap-iommu 41501000.mmu: 41501000.mmu registered
[    0.455249] omap-iommu 41502000.mmu: 41502000.mmu registered
[    0.458152] palmas 0-0058: Irq flag is 0x00000008
[    0.472649] palmas 0-0058: Muxing GPIO 2f, PWM 0, LED 0
[    0.554028] omap_i2c 48070000.i2c: bus 0 rev0.12 at 400 kHz
[    0.554526] omap_i2c 48060000.i2c: bus 2 rev0.12 at 400 kHz
[    0.555103] omap_i2c 4807c000.i2c: bus 4 rev0.12 at 400 kHz
[    0.555313] media: Linux media interface: v0.10
[    0.555368] Linux video capture interface: v2.00
[    0.555410] pps_core: LinuxPPS API ver. 1 registered
[    0.555417] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@...ux.it>
[    0.555443] PTP clock support registered
[    0.555490] EDAC MC: Ver: 3.0.0
[    0.556248] omap-mailbox 4883c000.mailbox: omap mailbox rev 0x400
[    0.556543] omap-mailbox 4883e000.mailbox: omap mailbox rev 0x400
[    0.556831] omap-mailbox 48840000.mailbox: omap mailbox rev 0x400
[    0.557123] omap-mailbox 48842000.mailbox: omap mailbox rev 0x400
[    0.557444] Advanced Linux Sound Architecture Driver Initialized.
[    0.558290] clocksource: Switched to clocksource arch_sys_counter
[    0.569416] NET: Registered protocol family 2
[    0.569913] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    0.569977] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[    0.570101] TCP: Hash tables configured (established 8192 bind 8192)
[    0.570149] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.570180] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.570325] NET: Registered protocol family 1
[    0.570361] RPC:       creating workqueue rpciod
[    0.570524] RPC:       registering /proc/net/rpc
[    0.570662] svc: Adding svc transport class 'tcp'
[    0.570670] svc: Adding svc transport class 'udp'
[    0.570687] RPC: Registered named UNIX socket transport module.
[    0.570694] RPC: Registered udp transport module.
[    0.570699] RPC: Registered tcp transport module.
[    0.570705] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.571727] hw perfevents: enabled with armv7_cortex_a15 PMU driver, 7 counters available
[    0.574145] futex hash table entries: 512 (order: 3, 32768 bytes)
[    0.582005] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.582247] RPC:       creating workqueue nfsiod
[    0.582620] RPC:       registering /proc/net/rpc/nfs
[    0.582669] NFS: Registering the id_resolver key type
[    0.582700] Key type id_resolver registered
[    0.582707] Key type id_legacy registered
[    0.582770] ntfs: driver 2.1.32 [Flags: R/O].
[    0.584763] bounce: pool size: 64 pages
[    0.584920] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 248)
[    0.584936] io scheduler noop registered
[    0.584949] io scheduler deadline registered
[    0.584984] io scheduler cfq registered (default)
[    0.589950] pinctrl-single 4a003400.pinmux: 282 pins at pa fc003400 size 1128
[    0.593494] PCI host bridge /ocp/axi@...cie@...00000 ranges:
[    0.593505]   No bus range found for /ocp/axi@...cie@...00000, using [bus 00-ff]
[    0.593536]    IO 0x20003000..0x20012fff -> 0x00000000
[    0.593556]   MEM 0x20013000..0x2fffffff -> 0x20013000
[    0.623979] dra7-pcie 51000000.pcie: link is not up
[    0.624163] dra7-pcie 51000000.pcie: PCI host bridge to bus 0000:00
[    0.624175] pci_bus 0000:00: root bus resource [bus 00-ff]
[    0.624185] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
[    0.624195] pci_bus 0000:00: root bus resource [mem 0x20013000-0x2fffffff]
[    0.624598] PCI: bus0: Fast back to back transfers disabled
[    0.638362] PCI: bus1: Fast back to back transfers disabled
[    0.638409] irq: no irq domain found for /ocp/axi@...cie@...00000/interrupt-controller !
[    0.638449] irq: no irq domain found for /ocp/axi@...cie@...00000/interrupt-controller !
[    0.638487] pci 0000:00:00.0: BAR 0: assigned [mem 0x20100000-0x201fffff]
[    0.638502] pci 0000:00:00.0: BAR 8: assigned [mem 0x20200000-0x202fffff]
[    0.638514] pci 0000:00:00.0: BAR 9: assigned [mem 0x20300000-0x203fffff pref]
[    0.638525] pci 0000:00:00.0: BAR 1: assigned [mem 0x20020000-0x2002ffff]
[    0.638538] pci 0000:00:00.0: BAR 7: assigned [io  0x1000-0x1fff]
[    0.638553] pci 0000:01:00.0: BAR 6: assigned [mem 0x20300000-0x2030ffff pref]
[    0.638564] pci 0000:01:00.0: BAR 5: assigned [mem 0x20200000-0x202001ff]
[    0.638584] pci 0000:01:00.0: BAR 4: assigned [io  0x1000-0x101f]
[    0.638603] pci 0000:01:00.0: BAR 0: assigned [io  0x1020-0x1027]
[    0.638621] pci 0000:01:00.0: BAR 2: assigned [io  0x1028-0x102f]
[    0.638639] pci 0000:01:00.0: BAR 1: assigned [io  0x1030-0x1033]
[    0.638658] pci 0000:01:00.0: BAR 3: assigned [io  0x1034-0x1037]
[    0.638676] pci 0000:00:00.0: PCI bridge to [bus 01]
[    0.638686] pci 0000:00:00.0:   bridge window [io  0x1000-0x1fff]
[    0.638698] pci 0000:00:00.0:   bridge window [mem 0x20200000-0x202fffff]
[    0.638708] pci 0000:00:00.0:   bridge window [mem 0x20300000-0x203fffff pref]
[    0.638936] pcieport 0000:00:00.0: Signaling PME through PCIe PME interrupt
[    0.638947] pci 0000:01:00.0: Signaling PME through PCIe PME interrupt
[    0.640117] backlight supply power not found, using dummy regulator
[    0.701389] Serial: 8250/16550 driver, 10 ports, IRQ sharing disabled
[    0.704755] 48020000.serial: ttyS2 at MMIO 0x48020000 (irq = 301, base_baud = 3000000) is a 8250
[    1.803275] console [ttyS2] enabled
[    1.807606] 48422000.serial: ttyS7 at MMIO 0x48422000 (irq = 302, base_baud = 3000000) is a 8250
[    1.817676] [drm] Initialized drm 1.1.0 20060810
[    1.824304] OMAP DSS rev 6.1
[    1.828074] omapdss_dss 58000000.dss: bound 58001000.dispc (ops dispc_component_ops)
[    1.836561] omapdss_dss 58000000.dss: bound 58040000.encoder (ops hdmi5_component_ops)
[    1.852730] loop: module loaded
[    1.858711] libphy: Fixed MDIO Bus: probed
[    1.908322] davinci_mdio 48485000.mdio: davinci mdio revision 1.6
[    1.914447] davinci_mdio 48485000.mdio: detected phy mask fffffff9
[    1.924982] libphy: 48485000.mdio: probed
[    1.929054] davinci_mdio 48485000.mdio: phy[1]: device 48485000.mdio:01, driver Micrel KSZ9031 Gigabit PHY
[    1.938788] davinci_mdio 48485000.mdio: phy[2]: device 48485000.mdio:02, driver Micrel KSZ9031 Gigabit PHY
[    1.949155] cpsw 48484000.ethernet: Detected MACID = 74:da:ea:47:8b:26
[    1.956425] cpsw 48484000.ethernet: cpsw: Detected MACID = 74:da:ea:47:8b:27
[    1.964968] mousedev: PS/2 mouse device common for all mice
[    1.971072] i2c /dev entries driver
[    1.977349] gpio-fan gpio_fan: GPIO fan initialized
[    1.983301] tmp102 0-0048: initialized
[    1.989999] omap_hsmmc 4809c000.mmc: Got CD GPIO
[    2.038843] omap_hsmmc 480b4000.mmc: no pinctrl state for sdr25 mode
[    2.045225] omap_hsmmc 480b4000.mmc: no pinctrl state for sdr12 mode
[    2.068430] vdd_3v3: supplied by regen1
[    2.149616] ledtrig-cpu: registered to indicate activity on CPUs
[    2.159632] davinci-mcasp 48468000.mcasp: ERRATA i868 workaround is enabled
[    2.167775] NET: Registered protocol family 10
[    2.183098] sit: IPv6 over IPv4 tunneling driver
[    2.188303] NET: Registered protocol family 17
[    2.192973] Key type dns_resolver registered
[    2.197370] omap_voltage_late_init: Voltage driver support not added
[    2.204273] Adding alias for supply vdd,cpu0 -> vdd,4a003b20.oppdm
[    2.210499] Adding alias for supply vbb,cpu0 -> vbb,4a003b20.oppdm
[    2.217194] Adding alias for supply vdd,cpu0 -> vdd,4a003b20.oppdm
[    2.223424] Adding alias for supply vbb,cpu0 -> vbb,4a003b20.oppdm
[    2.231589] Power Management for TI OMAP4+ devices.
[    2.236687] Registering SWP/SWPB emulation handler
[    2.243623] dmm 4e000000.dmm: initialized all PAT entries
[    2.271099] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
[    2.277741] [drm] No driver support for vblank timestamp query.
[    2.337700] mmc0: host does not support reading read-only switch, assuming write-enable
[    2.349180] mmc0: new high speed SDHC card at address aaaa
[    2.355029] mmcblk0: mmc0:aaaa SL08G 7.40 GiB 
[    2.360674]  mmcblk0: p1 p2 p3
[    2.422915] mmc1: MAN_BKOPS_EN bit is not set
[    2.435914] mmc1: new DDR MMC card at address 0001
[    2.451053] mmcblk1: mmc1:0001 S10004 3.56 GiB 
[    2.465778] mmcblk1boot0: mmc1:0001 S10004 partition 1 4.00 MiB
[    2.471891] mmcblk1boot1: mmc1:0001 S10004 partition 2 4.00 MiB
[    2.478728]  mmcblk1: p1 p2 p3
[    2.562262] [drm] Enabling DMM ywrap scrolling
[    2.600301] Console: switching to colour frame buffer device 100x30
[    2.608627] omapdrm omapdrm.0: fb0: omapdrm frame buffer device
[    2.638571] [drm] Initialized omapdrm 1.0.0 20110917 on minor 0
[    2.645862] input: gpio_keys as /devices/platform/gpio_keys/input/input0
[    2.652827] hctosys: unable to open rtc device (rtc0)
[    2.668349] net eth0: initializing cpsw version 1.15 (0)
[    2.673702] net eth0: initialized cpsw ale version 1.4
[    2.678878] net eth0: ALE Table size 1024
[    2.770336] net eth0: phy found : id is : 0x221622
[    2.781714] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[    6.776920] cpsw 48484000.ethernet eth0: Link is Up - 1Gbps/Full - flow control rx/tx
[    6.784829] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[    6.798309] Sending DHCP requests ., OK
[    6.848304] IP-Config: Got DHCP answer from 192.168.0.1, my address is 192.168.0.97
[    6.856129] IP-Config: Complete:
[    6.859400]      device=eth0, hwaddr=74:da:ea:47:8b:26, ipaddr=192.168.0.97, mask=255.255.255.0, gw=192.168.0.1
[    6.870013]      host=192.168.0.97, domain=ti.com, nis-domain=(none)
[    6.876395]      bootserver=0.0.0.0, rootserver=192.168.0.1, rootpath=
[    6.882795]      nameserver0=192.0.2.2, nameserver1=192.0.2.3
[    6.888933] aic_dvdd_fixed: disabling
[    6.892611] vmmcwl_fixed: disabling
[    6.896293] ldousb: disabling
[    6.899787] ALSA device list:
[    6.902765]   No soundcards found.
[    6.907052] Root-NFS: nfsroot=/home/tigtfarm10/NFS_exports/linux/am57xx-evm/autofs/f1a395609921e4cdad1b0bb2ec56f877,nolock,v3,tcp,rsize=4096,wsize=4096
[    6.920854] NFS: nfs mount opts='vers=2,udp,rsize=4096,wsize=4096,nolock,v3,tcp,rsize=4096,wsize=4096,nolock,addr=192.168.0.1'
[    6.932330] NFS:   parsing nfs mount option 'vers=2'
[    6.937399] NFS:   parsing nfs mount option 'udp'
[    6.942194] NFS:   parsing nfs mount option 'rsize=4096'
[    6.947561] NFS:   parsing nfs mount option 'wsize=4096'
[    6.952967] NFS:   parsing nfs mount option 'nolock'
[    6.957980] NFS:   parsing nfs mount option 'v3'
[    6.962725] NFS:   parsing nfs mount option 'tcp'
[    6.967607] NFS:   parsing nfs mount option 'rsize=4096'
[    6.972959] NFS:   parsing nfs mount option 'wsize=4096'
[    6.978359] NFS:   parsing nfs mount option 'nolock'
[    6.983345] NFS:   parsing nfs mount option 'addr=192.168.0.1'
[    6.989222] NFS: MNTPATH: '/home/tigtfarm10/NFS_exports/linux/am57xx-evm/autofs/f1a395609921e4cdad1b0bb2ec56f877'
[    6.999540] NFS: sending MNT request for 192.168.0.1:/home/tigtfarm10/NFS_exports/linux/am57xx-evm/autofs/f1a395609921e4cdad1b0bb2ec56f877
[    7.012046] RPC:       set up xprt to 192.168.0.1 (autobind) via tcp
[    7.018454] RPC:       created transport eddc9000 with 65536 slots
[    7.024659] RPC:       creating mount client for 192.168.0.1 (xprt eddc9000)
[    7.031785] RPC:       creating UNIX authenticator for client ee8ead00
[    7.038376] RPC:       new task initialized, procpid 1
[    7.043532] RPC:       allocated task edd8cc00
[    7.047993] RPC:     1 __rpc_execute flags=0x680
[    7.052636] RPC:     1 call_start mount3 proc NULL (sync)
[    7.058055] RPC:     1 call_reserve (status 0)
[    7.062524] RPC:     1 reserved req ee8eac00 xid 57c6e885
[    7.067944] RPC:       wake_up_first(eddc9100 "xprt_sending")
[    7.073725] RPC:     1 call_reserveresult (status 0)
[    7.078720] RPC:     1 call_refresh (status 0)
[    7.083180] RPC:     1 holding NULL cred c096c2f0
[    7.087901] RPC:     1 refreshing NULL cred c096c2f0
[    7.092894] RPC:     1 call_refreshresult (status 0)
[    7.097877] RPC:     1 call_allocate (status 0)
[    7.102432] RPC:     1 allocated buffer of size 92 at eddc9800
[    7.108302] RPC:     1 call_bind (status 0)
[    7.112502] RPC:     1 rpcb_getport_async(192.168.0.1, 100005, 3, 6)
[    7.118913] RPC:     1 sleep_on(queue "xprt_binding" time 4294938008)
[    7.125380] RPC:     1 added to queue eddc90a4 "xprt_binding"
[    7.131159] RPC:     1 setting alarm for 60000 ms
[    7.135884] RPC:     1 rpcb_getport_async: trying rpcbind version 2
[    7.142197] RPC:       set up xprt to 192.168.0.1 (port 111) via tcp
[    7.148601] RPC:       created transport eddca800 with 65536 slots
[    7.154805] RPC:       creating rpcbind client for 192.168.0.1 (xprt eddca800)
[    7.162115] RPC:       creating UNIX authenticator for client edd8f200
[    7.168679] RPC:       new task initialized, procpid 1
[    7.173835] RPC:       allocated task edd8cd00
[    7.178367] RPC:       rpc_release_client(edd8f200)
[    7.183285] RPC:     2 __rpc_execute flags=0x681
[    7.187919] RPC:     2 call_start rpcbind2 proc GETPORT (async)
[    7.193875] RPC:     2 call_reserve (status 0)
[    7.193893] RPC:     1 sync task going to sleep
[    7.202894] RPC:     2 reserved req edd8f100 xid 926299b2
[    7.208328] RPC:       wake_up_first(eddca900 "xprt_sending")
[    7.214096] RPC:     2 call_reserveresult (status 0)
[    7.219089] RPC:     2 call_refresh (status 0)
[    7.223549] RPC:     2 looking up UNIX cred
[    7.227745] RPC:       looking up UNIX cred
[    7.231958] RPC:       allocating UNIX cred for uid 0 gid 0
[    7.237553] RPC:     2 refreshing UNIX cred edd8cf00
[    7.242799] RPC:     2 call_refreshresult (status 0)
[    7.247782] RPC:     2 call_allocate (status 0)
[    7.252340] RPC:     2 allocated buffer of size 508 at eddcb000
[    7.258296] RPC:     2 call_bind (status 0)
[    7.262494] RPC:     2 call_connect xprt eddca800 is not connected
[    7.268713] RPC:     2 xprt_connect xprt eddca800 is not connected
[    7.274917] RPC:     2 sleep_on(queue "xprt_pending" time 4294938023)
[    7.281392] RPC:     2 added to queue eddca95c "xprt_pending"
[    7.287159] RPC:     2 setting alarm for 60000 ms
[    7.291939] RPC:       xs_connect scheduled xprt eddca800
[    7.297405] RPC:       worker connecting xprt eddca800 via tcp to 192.168.0.1 (port 111)
[    7.305897] RPC:       eddca800 connect status 115 connected 0 sock state 2
[    7.306109] RPC:       xs_tcp_state_change client eddca800...
[    7.306114] RPC:       state 1 conn 0 dead 0 zapped 1 sk_shutdown 0
[    7.306118] RPC:     2 __rpc_wake_up_task (now 4294938026)
[    7.306120] RPC:     2 disabling timer
[    7.306124] RPC:     2 removed from queue eddca95c "xprt_pending"
[    7.306134] RPC:       __rpc_wake_up_task done
[    7.316303] RPC:     2 __rpc_execute flags=0x681
[    7.316306] RPC:     2 xprt_connect_status: retrying
[    7.316310] RPC:     2 call_connect_status (status -11)
[    7.316313] RPC:     2 call_timeout (minor)
[    7.316315] RPC:     2 call_bind (status 0)
[    7.316319] RPC:     2 call_connect xprt eddca800 is connected
[    7.316322] RPC:     2 call_transmit (status 0)
[    7.316324] RPC:     2 xprt_prepare_transmit
[    7.316328] RPC:     2 failed to lock transport eddca800
[    7.316331] RPC:     2 sleep_on(queue "xprt_sending" time 4294938027)
[    7.316334] RPC:     2 added to queue eddca900 "xprt_sending"
[    7.400396] RPC:       wake_up_first(eddca900 "xprt_sending")
[    7.406168] RPC:     2 __rpc_wake_up_task (now 4294938036)
[    7.411684] RPC:     2 removed from queue eddca900 "xprt_sending"
[    7.417800] RPC:       __rpc_wake_up_task done
[    7.422290] RPC:     2 __rpc_execute flags=0x681
[    7.426965] RPC:     2 call_status (status -11)
[    7.431657] RPC:     2 call_transmit (status 0)
[    7.436202] RPC:     2 xprt_prepare_transmit
[    7.440498] RPC:     2 rpc_xdr_encode (status 0)
[    7.445129] RPC:     2 marshaling UNIX cred edd8cf00
[    7.450122] RPC:     2 using AUTH_UNIX cred edd8cf00 to wrap rpc data
[    7.456587] RPC:     2 encoding PMAP_GETPORT call (100005, 3, 6, 0)
[    7.462885] RPC:     2 xprt_transmit(92)
[    7.466841] RPC:       xs_tcp_send_request(92) = 0
[    7.467095] RPC:       xs_tcp_data_ready...
[    7.467130] RPC:       xs_tcp_data_recv started
[    7.467134] RPC:       reading TCP record fragment of length 28
[    7.467136] RPC:       reading XID (4 bytes)
[    7.467138] RPC:       reading request with XID 926299b2
[    7.467140] RPC:       reading CALL/REPLY flag (4 bytes)
[    7.467142] RPC:       read reply XID 926299b2
[    7.467145] RPC:       XID 926299b2 read 20 bytes
[    7.467148] RPC:       xprt = eddca800, tcp_copied = 28, tcp_offset = 28, tcp_reclen = 28
[    7.467151] RPC:     2 xid 926299b2 complete (28 bytes received)
[    7.467154] RPC:       xs_tcp_data_recv done
[    7.528985] RPC:     2 xmit complete
[    7.532571] RPC:       wake_up_first(eddca900 "xprt_sending")
[    7.538348] RPC:     2 call_status (status 28)
[    7.542806] RPC:     2 call_decode (status 28)
[    7.547263] RPC:     2 validating UNIX cred edd8cf00
[    7.552255] RPC:     2 using AUTH_UNIX cred edd8cf00 to unwrap rpc data
[    7.558920] RPC:     2 PMAP_GETPORT result: 41203
[    7.563638] RPC:     2 call_decode result 0
[    7.567834] RPC:       setting port for xprt eddc9000 to 41203
[    7.573698] RPC:     2 rpcb_getport_done(status 0, port 41203)
[    7.579561] RPC:     2 return 0, status 0
[    7.583582] RPC:     2 release task
[    7.587081] RPC:       freeing buffer of size 508 at eddcb000
[    7.592856] RPC:     2 release request edd8f100
[    7.597401] RPC:       wake_up_first(eddca9b8 "xprt_backlog")
[    7.603177] RPC:       rpc_release_client(edd8f200)
[    7.608072] RPC:       destroying rpcbind client for 192.168.0.1
[    7.614135] RPC:       destroying transport eddca800
[    7.619150] RPC:       xs_destroy xprt eddca800
[    7.623695] RPC:       xs_close xprt eddca800
[    7.628078] RPC:       xs_tcp_state_change client eddca800...
[    7.633856] RPC:       state 4 conn 1 dead 0 zapped 1 sk_shutdown 3
[    7.640180] RPC:       xs_tcp_state_change client eddca800...
[    7.645947] RPC:       state 5 conn 0 dead 0 zapped 1 sk_shutdown 3
[    7.652265] RPC:       xs_tcp_state_change client eddca800...
[    7.658031] RPC:       state 7 conn 0 dead 0 zapped 1 sk_shutdown 3
[    7.664329] RPC:       disconnected transport eddca800
[    7.669493] RPC:       xs_tcp_state_change client eddca800...
[    7.675259] RPC:       state 7 conn 0 dead 0 zapped 1 sk_shutdown 3
[    7.681556] RPC:       disconnected transport eddca800
[    7.686711] RPC:       xs_tcp_data_ready...
[    7.690938] RPC:       disconnected transport eddca800
[    7.696099] RPC:     1 __rpc_wake_up_task (now 4294938065)
[    7.701613] RPC:     1 disabling timer
[    7.705374] RPC:     1 removed from queue eddc90a4 "xprt_binding"
[    7.711499] RPC:       __rpc_wake_up_task done

[GS] In good case "RPC:     2 freeing task" can be seen here

[    7.711506] RPC:     1 sync task resuming
[    7.711510] RPC:     1 call_bind_status (status 0)
[    7.711512] RPC:     1 call_connect xprt eddc9000 is not connected
[    7.711515] RPC:     1 xprt_connect xprt eddc9000 is not connected
[    7.711519] RPC:     1 sleep_on(queue "xprt_pending" time 4294938067)
[    7.711521] RPC:     1 added to queue eddc915c "xprt_pending"
[    7.711523] RPC:     1 setting alarm for 60000 ms
[    7.711527] RPC:       xs_connect scheduled xprt eddc9000
[    7.711534] RPC:     1 sync task going to sleep
[    7.711557] RPC:       xs_bind 0.0.0.0:872: ok (0)
[    7.711560] RPC:       worker connecting xprt eddc9000 via tcp to 192.168.0.1 (port 41203)
[    7.711604] RPC:       eddc9000 connect status 115 connected 0 sock state 2
[    7.711607] RPC:       wake_up_first(eddc9100 "xprt_sending")
[    7.711733] RPC:       xs_tcp_state_change client eddc9000...
[    7.711737] RPC:       state 1 conn 0 dead 0 zapped 1 sk_shutdown 0
[    7.711740] RPC:     1 __rpc_wake_up_task (now 4294938067)
[    7.711741] RPC:     1 disabling timer
[    7.711744] RPC:     1 removed from queue eddc915c "xprt_pending"
[    7.711750] RPC:       __rpc_wake_up_task done
[    7.711790] RPC:     1 sync task resuming
[    7.711793] RPC:     1 xprt_connect_status: retrying
[    7.711796] RPC:     1 call_connect_status (status -11)
[    7.711797] RPC:     1 call_timeout (minor)
[    7.711799] RPC:     1 call_bind (status 0)
[    7.711802] RPC:     1 call_connect xprt eddc9000 is connected
[    7.711803] RPC:     1 call_transmit (status 0)
[    7.711805] RPC:     1 xprt_prepare_transmit
[    7.711808] RPC:     1 rpc_xdr_encode (status 0)

[GS] =OR= In good case "RPC:     2 freeing task" can be seen here

[    7.711809] RPC:     1 marshaling NULL cred c096c2f0
[    7.711812] RPC:     1 using AUTH_NULL cred c096c2f0 to wrap rpc data
[    7.711814] RPC:     1 xprt_transmit(44)
[    7.711839] RPC:       xs_tcp_send_request(44) = 0
[    7.711841] RPC:     1 xmit complete
[    7.711844] RPC:     1 sleep_on(queue "xprt_pending" time 4294938067)
[    7.711846] RPC:     1 added to queue eddc915c "xprt_pending"
[    7.711848] RPC:     1 setting alarm for 60000 ms
[    7.711852] RPC:       wake_up_first(eddc9100 "xprt_sending")
[    7.711855] RPC:     1 sync task going to sleep
[    7.712063] RPC:       xs_tcp_data_ready...
[    7.712091] RPC:       xs_tcp_data_recv started
[    7.712094] RPC:       reading TCP record fragment of length 24
[    7.712096] RPC:       reading XID (4 bytes)
[    7.712098] RPC:       reading request with XID 57c6e885
[    7.712101] RPC:       reading CALL/REPLY flag (4 bytes)
[    7.712102] RPC:       read reply XID 57c6e885
[    7.712105] RPC:       XID 57c6e885 read 16 bytes
[    7.712107] RPC:       xprt = eddc9000, tcp_copied = 24, tcp_offset = 24, tcp_reclen = 24
[    7.712110] RPC:     1 xid 57c6e885 complete (24 bytes received)
[    7.712113] RPC:     1 __rpc_wake_up_task (now 4294938067)
[    7.712114] RPC:     1 disabling timer
[    7.712117] RPC:     1 removed from queue eddc915c "xprt_pending"
[    7.712123] RPC:       __rpc_wake_up_task done
[    7.712129] RPC:     1 sync task resuming
[    7.712131] RPC:     1 call_status (status 24)
[    7.712134] RPC:     1 call_decode (status 24)
[    7.712136] RPC:     1 validating NULL cred c096c2f0
[    7.712140] RPC:     1 using AUTH_NULL cred c096c2f0 to unwrap rpc data
[    7.712141] RPC:     1 call_decode result 0
[    7.712144] RPC:     1 return 0, status 0
[    7.712145] RPC:     1 release task
[    7.712150] RPC:       freeing buffer of size 92 at eddc9800
[    7.712153] RPC:     1 release request ee8eac00
[    7.712154] RPC:       wake_up_first(eddc91b8 "xprt_backlog")
[    7.712157] RPC:       rpc_release_client(ee8ead00)
[    7.712160] RPC:     1 freeing task
[    7.712164] RPC:       new task initialized, procpid 1
[    7.712166] RPC:       allocated task ee257300
[    7.712169] RPC:     3 __rpc_execute flags=0x1280
[    7.712171] RPC:     3 call_start mount3 proc MOUNT (sync)
[    7.712173] RPC:     3 call_reserve (status 0)
[    7.712176] RPC:     3 reserved req ee8eac00 xid 58c6e885
[    7.712179] RPC:       wake_up_first(eddc9100 "xprt_sending")
[    7.712182] RPC:     3 call_reserveresult (status 0)
[    7.712184] RPC:     3 call_refresh (status 0)
[    7.712186] RPC:     3 looking up UNIX cred
[    7.712188] RPC:       looking up UNIX cred
[    7.712191] RPC:     3 refreshing UNIX cred edd8cf00
[    7.712193] RPC:     3 call_refreshresult (status 0)
[    7.712195] RPC:     3 call_allocate (status 0)
[    7.712198] RPC:     3 allocated buffer of size 1604 at eeb5f000
[    7.712200] RPC:     3 call_bind (status 0)
[    7.712202] RPC:     3 call_connect xprt eddc9000 is connected
[    7.712204] RPC:     3 call_transmit (status 0)
[    7.712205] RPC:     3 xprt_prepare_transmit
[    7.712208] RPC:     3 rpc_xdr_encode (status 0)
[    7.712209] RPC:     3 marshaling UNIX cred edd8cf00
[    7.712212] RPC:     3 using AUTH_UNIX cred edd8cf00 to wrap rpc data
[    7.712215] RPC:     3 xprt_transmit(168)
[    7.712222] RPC:       xs_tcp_data_recv done
[    7.712257] RPC:       xs_tcp_send_request(168) = 0
[    7.712259] RPC:     3 xmit complete
[    7.712262] RPC:     3 sleep_on(queue "xprt_pending" time 4294938067)
[    7.712264] RPC:     3 added to queue eddc915c "xprt_pending"
[    7.712266] RPC:     3 setting alarm for 60000 ms
[    7.712269] RPC:       wake_up_first(eddc9100 "xprt_sending")
[    7.712273] RPC:     3 sync task going to sleep
[    7.721103] RPC:       xs_tcp_data_ready...
[    7.721123] RPC:       xs_tcp_data_recv started
[    7.721126] RPC:       reading TCP record fragment of length 76
[    7.721127] RPC:       reading XID (4 bytes)
[    7.721129] RPC:       reading reply for XID 58c6e885
[    7.721131] RPC:       reading CALL/REPLY flag (4 bytes)
[    7.721133] RPC:       read reply XID 58c6e885
[    7.721136] RPC:       XID 58c6e885 read 68 bytes
[    7.721139] RPC:       xprt = eddc9000, tcp_copied = 76, tcp_offset = 76, tcp_reclen = 76
[    7.721141] RPC:     3 xid 58c6e885 complete (76 bytes received)
[    7.721144] RPC:     3 __rpc_wake_up_task (now 4294938068)
[    7.721145] RPC:     3 disabling timer
[    7.721147] RPC:     3 removed from queue eddc915c "xprt_pending"
[    7.721154] RPC:       __rpc_wake_up_task done
[    7.721159] RPC:     3 sync task resuming
[    7.721162] RPC:     3 call_status (status 76)
[    7.721164] RPC:     3 call_decode (status 76)
[    7.721166] RPC:     3 validating UNIX cred edd8cf00
[    7.721169] RPC:     3 using AUTH_UNIX cred edd8cf00 to unwrap rpc data
[    7.721171] NFS: received 1 auth flavors
[    7.721173] NFS:   auth flavor[0]: 1
[    7.721175] RPC:     3 call_decode result 0
[    7.721177] RPC:     3 return 0, status 0
[    7.721178] RPC:     3 release task
[    7.721182] RPC:       freeing buffer of size 1604 at eeb5f000
[    7.721186] RPC:     3 release request ee8eac00
[    7.721188] RPC:       wake_up_first(eddc91b8 "xprt_backlog")
[    7.721191] RPC:       rpc_release_client(ee8ead00)
[    7.721194] RPC:     3 freeing task
[    7.721197] RPC:       shutting down mount client for 192.168.0.1
[    7.721198] RPC:       rpc_release_client(ee8ead00)
[    7.721200] RPC:       destroying UNIX authenticator c096c324
[    7.721205] RPC:       destroying mount client for 192.168.0.1
[    7.721238] NFS: MNT request succeeded
[    7.721241] NFS: attempting to use auth flavor 1
[    7.721257] --> nfs_init_server()
[    7.721260] --> nfs_get_client(192.168.0.1,v3)
[    7.721264] RPC:       looking up machine cred for service *
[    7.721269] RPC:       allocated machine cred ee257300 for uid 0 gid 0
[    7.721279] RPC:       set up xprt to 192.168.0.1 (autobind) via tcp
[    7.721296] RPC:       created transport eeb5f800 with 65536 slots
[    7.721299] RPC:       creating nfs client for 192.168.0.1 (xprt eeb5f800)
[    7.721333] RPC:       creating UNIX authenticator for client ee24f600
[    7.721336] RPC:       new task initialized, procpid 1
[    7.721338] RPC:       allocated task ee257380
[    7.721341] RPC:     4 __rpc_execute flags=0x680
[    7.721344] RPC:     4 call_start nfs3 proc NULL (sync)
[    7.721347] RPC:     4 call_reserve (status 0)
[    7.721350] RPC:     4 reserved req ee24f500 xid 799833c3
[    7.721353] RPC:       wake_up_first(eeb5f900 "xprt_sending")
[    7.721356] RPC:     4 call_reserveresult (status 0)
[    7.721357] RPC:     4 call_refresh (status 0)
[    7.721360] RPC:     4 holding NULL cred c096c2f0
[    7.721362] RPC:     4 refreshing NULL cred c096c2f0
[    7.721364] RPC:     4 call_refreshresult (status 0)
[    7.721367] RPC:     4 call_allocate (status 0)
[    7.721369] RPC:     4 allocated buffer of size 92 at ee2ac800
[    7.721371] RPC:     4 call_bind (status 0)
[    7.721374] RPC:     4 rpcb_getport_async(192.168.0.1, 100003, 3, 6)
[    7.721376] RPC:     4 sleep_on(queue "xprt_binding" time 4294938068)
[    7.721378] RPC:     4 added to queue eeb5f8a4 "xprt_binding"
[    7.721380] RPC:     4 setting alarm for 60000 ms
[    7.721385] RPC:     4 rpcb_getport_async: trying rpcbind version 2
[    7.721393] RPC:       set up xprt to 192.168.0.1 (port 111) via tcp
[    7.721407] RPC:       created transport ee2ac000 with 65536 slots
[    7.721409] RPC:       creating rpcbind client for 192.168.0.1 (xprt ee2ac000)
[    7.721432] RPC:       creating UNIX authenticator for client ee24f900
[    7.721435] RPC:       new task initialized, procpid 1
[    7.721437] RPC:       allocated task ee257480
[    7.721440] RPC:       rpc_release_client(ee24f900)
[    7.721442] RPC:     4 sync task going to sleep
[    7.721450] RPC:       xs_tcp_data_recv done
[    7.721458] RPC:     5 __rpc_execute flags=0x681
[    7.721460] RPC:     5 call_start rpcbind2 proc GETPORT (async)
[    7.721462] RPC:     5 call_reserve (status 0)
[    7.721465] RPC:     5 reserved req ee24f800 xid 9916d160
[    7.721468] RPC:       wake_up_first(ee2ac100 "xprt_sending")
[    7.721471] RPC:     5 call_reserveresult (status 0)
[    7.721473] RPC:     5 call_refresh (status 0)
[    7.721474] RPC:     5 looking up UNIX cred
[    7.721476] RPC:       looking up UNIX cred
[    7.721478] RPC:       allocating UNIX cred for uid 0 gid 0
[    7.721480] RPC:     5 refreshing UNIX cred ee257500
[    7.721482] RPC:     5 call_refreshresult (status 0)
[    7.721485] RPC:     5 call_allocate (status 0)
[    7.721487] RPC:     5 allocated buffer of size 508 at ee2ad800
[    7.721489] RPC:     5 call_bind (status 0)
[    7.721491] RPC:     5 call_connect xprt ee2ac000 is not connected
[    7.721493] RPC:     5 xprt_connect xprt ee2ac000 is not connected
[    7.721497] RPC:     5 sleep_on(queue "xprt_pending" time 4294938068)
[    7.721498] RPC:     5 added to queue ee2ac15c "xprt_pending"
[    7.721500] RPC:     5 setting alarm for 60000 ms
[    7.721504] RPC:       xs_connect scheduled xprt ee2ac000
[    7.721514] RPC:       worker connecting xprt ee2ac000 via tcp to 192.168.0.1 (port 111)
[    7.721555] RPC:       ee2ac000 connect status 115 connected 0 sock state 2
[    7.721558] RPC:       wake_up_first(ee2ac100 "xprt_sending")
[    7.721687] RPC:       xs_tcp_state_change client ee2ac000...
[    7.721690] RPC:       state 1 conn 0 dead 0 zapped 1 sk_shutdown 0
[    7.721693] RPC:     5 __rpc_wake_up_task (now 4294938068)
[    7.721695] RPC:     5 disabling timer
[    7.721697] RPC:     5 removed from queue ee2ac15c "xprt_pending"
[    7.721703] RPC:       __rpc_wake_up_task done
[    7.721744] RPC:     5 __rpc_execute flags=0x681
[    7.721746] RPC:     5 xprt_connect_status: retrying
[    7.721748] RPC:     5 call_connect_status (status -11)
[    7.721750] RPC:     5 call_timeout (minor)
[    7.721752] RPC:     5 call_bind (status 0)
[    7.721755] RPC:     5 call_connect xprt ee2ac000 is connected
[    7.721756] RPC:     5 call_transmit (status 0)
[    7.721758] RPC:     5 xprt_prepare_transmit
[    7.721760] RPC:     5 rpc_xdr_encode (status 0)
[    7.721762] RPC:     5 marshaling UNIX cred ee257500
[    7.721765] RPC:     5 using AUTH_UNIX cred ee257500 to wrap rpc data
[    7.721768] RPC:     5 encoding PMAP_GETPORT call (100003, 3, 6, 0)
[    7.721769] RPC:     5 xprt_transmit(92)
[    7.721796] RPC:       xs_tcp_send_request(92) = 0
[    7.721798] RPC:     5 xmit complete
[    7.721800] RPC:     5 sleep_on(queue "xprt_pending" time 4294938068)
[    7.721803] RPC:     5 added to queue ee2ac15c "xprt_pending"
[    7.721805] RPC:     5 setting alarm for 60000 ms
[    7.721808] RPC:       wake_up_first(ee2ac100 "xprt_sending")
[    7.722037] RPC:       xs_tcp_data_ready...
[    7.722066] RPC:       xs_tcp_data_recv started
[    7.722069] RPC:       reading TCP record fragment of length 28
[    7.722071] RPC:       reading XID (4 bytes)
[    7.722073] RPC:       reading request with XID 9916d160
[    7.722075] RPC:       reading CALL/REPLY flag (4 bytes)
[    7.722076] RPC:       read reply XID 9916d160
[    7.722079] RPC:       XID 9916d160 read 20 bytes
[    7.722082] RPC:       xprt = ee2ac000, tcp_copied = 28, tcp_offset = 28, tcp_reclen = 28
[    7.722084] RPC:     5 xid 9916d160 complete (28 bytes received)
[    7.722087] RPC:     5 __rpc_wake_up_task (now 4294938068)
[    7.722088] RPC:     5 disabling timer
[    7.722091] RPC:     5 removed from queue ee2ac15c "xprt_pending"
[    7.722093] RPC:       __rpc_wake_up_task done
[    7.722095] RPC:       xs_tcp_data_recv done
[    7.722101] RPC:     5 __rpc_execute flags=0xe81
[    7.722103] RPC:     5 call_status (status 28)
[    7.722105] RPC:     5 call_decode (status 28)
[    7.722108] RPC:     5 validating UNIX cred ee257500
[    7.722110] RPC:     5 using AUTH_UNIX cred ee257500 to unwrap rpc data
[    7.722112] RPC:     5 PMAP_GETPORT result: 2049
[    7.722114] RPC:     5 call_decode result 0
[    7.722116] RPC:       setting port for xprt eeb5f800 to 2049
[    7.722120] RPC:     5 rpcb_getport_done(status 0, port 2049)
[    7.722122] RPC:     5 return 0, status 0
[    7.722123] RPC:     5 release task
[    7.722128] RPC:       freeing buffer of size 508 at ee2ad800
[    7.722131] RPC:     5 release request ee24f800
[    7.722132] RPC:       wake_up_first(ee2ac1b8 "xprt_backlog")
[    7.722135] RPC:       rpc_release_client(ee24f900)
[    7.722138] RPC:       destroying rpcbind client for 192.168.0.1
[    7.722165] RPC:       destroying transport ee2ac000
[    7.722185] RPC:       xs_destroy xprt ee2ac000
[    7.722188] RPC:       xs_close xprt ee2ac000
[    7.722212] RPC:       xs_tcp_state_change client ee2ac000...
[    7.722215] RPC:       state 4 conn 1 dead 0 zapped 1 sk_shutdown 3
[    7.722225] RPC:       disconnected transport ee2ac000
[    7.722232] RPC:     4 __rpc_wake_up_task (now 4294938068)
[    7.722234] RPC:     4 disabling timer
[    7.722236] RPC:     4 removed from queue eeb5f8a4 "xprt_binding"
[    7.722243] RPC:       __rpc_wake_up_task done
[    7.722249] RPC:     4 sync task resuming
[    7.722251] RPC:     4 call_bind_status (status 0)
[    7.722253] RPC:     4 call_connect xprt eeb5f800 is not connected
[    7.722255] RPC:     4 xprt_connect xprt eeb5f800 is not connected
[    7.722258] RPC:     4 sleep_on(queue "xprt_pending" time 4294938068)
[    7.722261] RPC:     4 added to queue eeb5f95c "xprt_pending"
[    7.722263] RPC:     4 setting alarm for 60000 ms
[    7.722266] RPC:       xs_connect scheduled xprt eeb5f800
[    7.722270] RPC:     4 sync task going to sleep
[    7.722276] RPC:     5 freeing task
[    7.722289] RPC:       xs_bind 0.0.0.0:936: ok (0)
[    7.722292] RPC:       worker connecting xprt eeb5f800 via tcp to 192.168.0.1 (port 2049)
[    7.722371] RPC:       eeb5f800 connect status 115 connected 0 sock state 2
[    7.722379] RPC:       wake_up_first(eeb5f900 "xprt_sending")
[    8.988298] omap_i2c 48070000.i2c: controller timed out
[    9.128222] RPC:       destroying transport eddc9000
[    9.133237] RPC:       xs_destroy xprt eddc9000
[    9.137782] RPC:       xs_close xprt eddc9000
[    9.142179] RPC:       xs_tcp_state_change client eddc9000...
[    9.147945] RPC:       state 4 conn 1 dead 0 zapped 1 sk_shutdown 3
[    9.148286] RPC:       unx_free_cred edd8cf00
[    9.158642] RPC:       xs_tcp_state_change client eddc9000...
[    9.164411] RPC:       state 5 conn 0 dead 0 zapped 1 sk_shutdown 3
[    9.170724] RPC:       xs_tcp_state_change client eddc9000...
[    9.176489] RPC:       state 7 conn 0 dead 0 zapped 1 sk_shutdown 3
[    9.182789] RPC:       disconnected transport eddc9000
[    9.187944] RPC:       xs_tcp_state_change client eddc9000...
[    9.193719] RPC:       state 7 conn 0 dead 0 zapped 1 sk_shutdown 3
[    9.200016] RPC:       disconnected transport eddc9000
[    9.205170] RPC:       xs_tcp_data_ready...
[    9.209402] RPC:       disconnected transport eddc9000
[    9.214586] RPC:     2 freeing task

[GS] This is failed sequence ^^^^^


[   62.749957] random: nonblocking pool is initialized
[   67.838287] RPC:     4 timeout
[   67.841361] RPC:     4 __rpc_wake_up_task (now 4294944080)
[   67.846868] RPC:     4 disabling timer
[   67.850647] RPC:     4 removed from queue eeb5f95c "xprt_pending"
[   67.856775] RPC:       __rpc_wake_up_task done
[   67.861262] RPC:     4 sync task resuming
[   67.865286] RPC:     4 xprt_connect_status: connect attempt timed out
[   67.871787] RPC:     4 call_connect_status (status -110)
[   67.877124] RPC:     4 call_timeout (minor)
[   67.881339] RPC:     4 call_bind (status 0)
[   67.885543] RPC:     4 call_connect xprt eeb5f800 is not connected
[   67.891766] RPC:     4 xprt_connect xprt eeb5f800 is not connected
[   67.897973] RPC:     4 sleep_on(queue "xprt_pending" time 4294944085)
[   67.904456] RPC:     4 added to queue eeb5f95c "xprt_pending"
[   67.910241] RPC:     4 setting alarm for 120000 ms
[   67.915055] RPC:     4 sync task going to sleep
[  135.038293] RPC:       xs_error_report client eeb5f800, error=110...
[  135.044676] RPC:     4 __rpc_wake_up_task (now 4294950800)
[  135.050188] RPC:     4 disabling timer
[  135.053957] RPC:     4 removed from queue eeb5f95c "xprt_pending"
[  135.060079] RPC:       __rpc_wake_up_task done
[  135.064542] RPC:       xs_tcp_state_change client eeb5f800...
[  135.070317] RPC:       state 7 conn 0 dead 0 zapped 1 sk_shutdown 3
[  135.076609] RPC:       disconnected transport eeb5f800
[  135.081790] RPC:     4 sync task resuming
[  135.085819] RPC:     4 xprt_connect_status: connect attempt timed out
[  135.092334] RPC:     4 call_connect_status (status -110)
[  135.097667] RPC:     4 call_timeout (minor)
[  135.101888] RPC:     4 call_bind (status 0)
[  135.106087] RPC:     4 call_connect xprt eeb5f800 is not connected
[  135.112305] RPC:     4 xprt_connect xprt eeb5f800 is not connected
[  135.118531] RPC:     4 sleep_on(queue "xprt_pending" time 4294950808)
[  135.125002] RPC:     4 added to queue eeb5f95c "xprt_pending"
[  135.130786] RPC:     4 setting alarm for 180000 ms
[  135.135604] RPC:       xs_connect delayed xprt eeb5f800 for 3 seconds
[  135.142083] RPC:       xs_tcp_state_change client eeb5f800...
[  135.147852] RPC:       state 7 conn 0 dead 0 zapped 1 sk_shutdown 3
[  135.154159] RPC:       disconnected transport eeb5f800
[  135.159328] RPC:     4 __rpc_wake_up_task (now 4294950812)
[  135.164833] RPC:     4 disabling timer
[  135.168614] RPC:     4 removed from queue eeb5f95c "xprt_pending"
[  135.174730] RPC:       __rpc_wake_up_task done
[  135.179231] RPC:     4 xprt_connect_status: retrying
[  135.184221] RPC:     4 call_connect_status (status -11)
[  135.189510] RPC:     4 call_timeout (minor)
[  135.193709] RPC:     4 call_bind (status 0)
[  135.197908] RPC:     4 call_connect xprt eeb5f800 is not connected
[  135.204158] RPC:     4 xprt_connect xprt eeb5f800 is not connected
[  135.210443] RPC:     4 failed to lock transport eeb5f800
[  135.215785] RPC:     4 sleep_on(queue "xprt_sending" time 4294950817)
[  135.222280] RPC:     4 added to queue eeb5f900 "xprt_sending"
[  135.228065] RPC:     4 sync task going to sleep
[  138.188320] RPC:       xs_bind 0.0.0.0:936: ok (0)
[  138.193139] RPC:       worker connecting xprt eeb5f800 via tcp to 192.168.0.1 (port 2049)
[  138.201418] RPC:       eeb5f800 connect status 115 connected 0 sock state 2
[  138.208433] RPC:       wake_up_first(eeb5f900 "xprt_sending")
[  138.214202] RPC:     4 __rpc_wake_up_task (now 4294951117)
[  138.219723] RPC:     4 removed from queue eeb5f900 "xprt_sending"
[  138.225851] RPC:       __rpc_wake_up_task done
[  138.230344] RPC:     4 sync task resuming
[  138.234369] RPC:     4 call_connect_status (status -11)
[  138.239664] RPC:     4 call_timeout (minor)
[  138.243870] RPC:     4 call_bind (status 0)
[  138.248070] RPC:     4 call_connect xprt eeb5f800 is not connected
[  138.254295] RPC:     4 xprt_connect xprt eeb5f800 is not connected
[  138.260520] RPC:     4 sleep_on(queue "xprt_pending" time 4294951122)
[  138.266987] RPC:     4 added to queue eeb5f95c "xprt_pending"
[  138.272772] RPC:     4 setting alarm for 180000 ms
[  138.277588] RPC:     4 sync task going to sleep

- 12:26:16 [INFO] Boot attempt 1/1 failed
- 12:26:16 [INFO] Collecting kernel traces via sysrq...
- 12:26:27 [INFO] [  208.203437] sysrq: SysRq : Show State
[  208.207123]   task                PC stack   pid father
[  208.212370] swapper/0       D c0660fe0     0     1      0 0x00000000
[  208.218765] Backtrace: 
[  208.221239] [<c0660cfc>] (__schedule) from [<c06613c0>] (schedule+0x54/0xc4)
[  208.228316]  r10:ee318e00 r9:fffffe00 r8:c063b54c r7:eeda1db4 r6:ee88da34 r5:00000082
[  208.236216]  r4:ee88c000
[  208.238772] [<c066136c>] (schedule) from [<c063b57c>] (rpc_wait_bit_killable+0x30/0xe4)
[  208.246808]  r5:00000082 r4:00000082
[  208.250416] [<c063b54c>] (rpc_wait_bit_killable) from [<c066195c>] (__wait_on_bit+0x8c/0xcc)
[  208.258886]  r5:00000082 r4:ee88da28
[  208.262492] [<c06618d0>] (__wait_on_bit) from [<c0661a10>] (out_of_line_wait_on_bit+0x74/0x7c)
[  208.271137]  r9:fffffe00 r8:00000000 r7:ee2573b8 r6:00000001 r5:ee890000 r4:00000000
[  208.278952] [<c066199c>] (out_of_line_wait_on_bit) from [<c063c4a0>] (__rpc_execute+0x20c/0x394)
[  208.287772]  r7:ee2573b8 r6:c096c8f4 r5:eeb5f95c r4:ee257380
[  208.293487] [<c063c294>] (__rpc_execute) from [<c063c950>] (rpc_execute+0x6c/0x70)
[  208.301085]  r9:c067b694 r8:ee2a0910 r7:c0965a40 r6:c0965a40 r5:00000000 r4:ee257380
[  208.308902] [<c063c8e4>] (rpc_execute) from [<c0634bb0>] (rpc_run_task+0xac/0xb4)
[  208.316413]  r5:ee88dad4 r4:ee257380
[  208.320017] [<c0634b04>] (rpc_run_task) from [<c0634c00>] (rpc_call_sync+0x48/0xc4)
[  208.327702]  r5:ee88dbc4 r4:ee24f600
[  208.331307] [<c0634bb8>] (rpc_call_sync) from [<c0634cd8>] (rpc_ping+0x5c/0x78)
[  208.338644]  r4:ee24f600
[  208.341194] [<c0634c7c>] (rpc_ping) from [<c0634dac>] (rpc_create_xprt+0xb8/0xd0)
[  208.348705]  r4:ee24f600
[  208.351254] [<c0634cf4>] (rpc_create_xprt) from [<c0634e78>] (rpc_create+0xb4/0x1c4)
[  208.359028]  r7:c0965a40 r6:c0965a40 r5:00000000 r4:ee88dbc4
[  208.364743] [<c0634dc4>] (rpc_create) from [<c01e1abc>] (nfs_create_rpc_client+0xdc/0x12c)
[  208.373039]  r6:ee88dc94 r5:00000001 r4:ee318e00
[  208.377698] [<c01e19e0>] (nfs_create_rpc_client) from [<c01e2778>] (nfs_init_client+0x3c/0xd8)
[  208.386343]  r6:eeafefec r5:ee88dca8 r4:ee318e00
[  208.391002] [<c01e273c>] (nfs_init_client) from [<c01e1840>] (nfs_get_client+0x254/0x3c4)
[  208.399209]  r5:ee88dca8 r4:eeafef18
[  208.402813] [<c01e15ec>] (nfs_get_client) from [<c01e2994>] (nfs_create_server+0xbc/0x4cc)
[  208.411109]  r10:c09313d4 r9:ee88ddc4 r8:ee24dcc0 r7:ee88dca8 r6:c096c8f0 r5:eeb5f000
[  208.419006]  r4:ee2a0800
[  208.421559] [<c01e28d8>] (nfs_create_server) from [<c01fa574>] (nfs3_create_server+0x10/0x28)
[  208.430117]  r10:00000001 r9:edd8ca80 r8:c09313d4 r7:c096c8f0 r6:ee88ddc4 r5:00000000
[  208.438016]  r4:ee2a0800
[  208.440568] [<c01fa564>] (nfs3_create_server) from [<c01ee8a8>] (nfs_try_mount+0xe4/0x340)
[  208.448865]  r5:00000000 r4:ee2a0800
[  208.452474] [<c01ee7c4>] (nfs_try_mount) from [<c01ee14c>] (nfs_fs_mount+0x624/0xb78)
[  208.460333]  r10:00000400 r9:00008000 r8:edd8ca8c r7:edd8ca80 r6:c096c8f0 r5:c01ee7c4
[  208.468232]  r4:c09313d4
[  208.470787] [<c01edb28>] (nfs_fs_mount) from [<c0120a90>] (mount_fs+0x1c/0xac)
[  208.478037]  r10:c0930e40 r9:c0928c94 r8:c0930e40 r7:c0930e40 r6:00008000 r5:edd8ca80
[  208.485936]  r4:c01edb28
[  208.488490] [<c0120a74>] (mount_fs) from [<c0139acc>] (vfs_kern_mount+0x50/0xf8)
[  208.495914]  r8:edd8e000 r7:c0930e40 r6:00008000 r5:edd8ca80 r4:edd71900
[  208.502681] [<c0139a7c>] (vfs_kern_mount) from [<c013cbb4>] (do_mount+0x1a8/0xc20)
[  208.510278]  r9:c0928c94 r8:edd68c40 r7:edd8ca80 r6:00008000 r5:00000020 r4:edd8e000
[  208.518094] [<c013ca0c>] (do_mount) from [<c013d9a0>] (SyS_mount+0x7c/0xa8)
[  208.525081]  r10:c090283c r9:c08c25ec r8:00008000 r7:c07eff78 r6:00000000 r5:edd8ca80
[  208.532979]  r4:edd68c40
[  208.535532] [<c013d924>] (SyS_mount) from [<c08c3494>] (mount_root+0x70/0x12c)
[  208.542781]  r8:c091071c r7:00000006 r6:00000005 r5:c091b888 r4:c0972024
[  208.549549] [<c08c3424>] (mount_root) from [<c08c36b0>] (prepare_namespace+0x160/0x1a4)
[  208.557584]  r7:c0972000 r6:c0972000 r5:c0902871 r4:c0972024
[  208.563297] [<c08c3550>] (prepare_namespace) from [<c08c2fdc>] (kernel_init_freeable+0x274/0x284)
[  208.572203]  r5:c0902838 r4:00000008
[  208.575811] [<c08c2d68>] (kernel_init_freeable) from [<c0660444>] (kernel_init+0x18/0xf0)
[  208.584019]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c066042c
[  208.591918]  r4:c0972000
[  208.594472] [<c066042c>] (kernel_init) from [<c000fa88>] (ret_from_fork+0x14/0x2c)
[  208.602070]  r5:c066042c r4:00000000

-- 
regards,
-grygorii

Powered by blists - more mailing lists