[Fuchsia] DiskCachePerftest tests fatal page fault failures |
|
Issue descriptionDiskCachePerftest.CacheBackendPerformance and SimpleCacheBackendPerformance both fail with fatal page faults on fuchsia that terminate the entire test suite. The full output of the test execution on QEMU is as follows: out/fuchsia/bin/run_net_perftests --gtest_filter=DiskCachePerfTest.CacheBackendPerformance 2018-06-08 12:35:50,642:INFO:root:Connecting to Fuchsia using SSH. 2018-06-08 12:35:58,850:INFO:root:Connected! 2018-06-08 12:35:58,851:INFO:root:Attaching kernel logger. 2018-06-08 12:35:58,856:INFO:root:Copying package to target.[00000.000] multiboot: info @ 0xffffff8000009500 flags 0x24f [00000.000] multiboot: cmdline @ 0xffffff80002ac07e[00000.000] multiboot: ramdisk @ 002ad000..00677f20 [00000.000] bootdata: @ 0xffffff80002ad000 (3976992 bytes)[00000.000] PMM: boot reserve add [0x100000, 0x2a9fff] [00000.000] PMM: boot reserve add [0x2ad000, 0x677fff][00000.000] PMM: boot reserve marking WIRED [0x100000, 0x2a9fff] [00000.000] PMM: boot reserve marking WIRED [0x2ad000, 0x677fff][00000.000] [00000.000] welcome to Zircon [00000.000] [00000.000] INIT: cpu 0, calling hook 0xffffffff80197ff8 (global_prng_seed) at level 0x30000, flags 0x1 [00000.000] initializing vm pre-heap [00000.000] VM: marking boot alloc used range [0x678000, 0x678040) [00000.000] INIT: cpu 0, calling hook 0xffffffff801409d0 (elf_build_id)at level 0x4fffe, flags 0x1 [00000.000] INIT: cpu 0, calling hook 0xffffffff80140b54 (version) at level 0x4ffff, flags 0x1 [00000.000] version: [00000.000] arch: x86 [00000.000] platform: pc [00000.000] target: pc [00000.000] project: x64 [00000.000] buildid: git-b4404bdb53fc3c220d3774f5d632c953f13bb409 [00000.000] ELF build ID: 67a050ec7aaa8c30990f4ba0ba45dac4de3ae45a [00000.000] initializing heap [00000.000] INIT: cpu 0, calling hook 0xffffffff80196cbc (console) at level 0x50000, flags 0x1 [00000.000] initializing vm [00000.000] VM: reserving kernel region [0xffffffff80100000, 0xffffffff801d8000) flags 0x28 name 'kernel_code' [00000.000] VM: reserving kernel region [0xffffffff801d8000, 0xffffffff80215000) flags 0x8 name 'kernel_rodata' [00000.000] VM: reserving kernel region [0xffffffff80215000, 0xffffffff8021c000) flags 0x18 name 'kernel_data' [00000.000] VM: reserving kernel region [0xffffffff8021c000, 0xffffffff802aa000) flags 0x18 name 'kernel_bss' [00000.000] INIT: cpu 0, calling hook 0xffffffff80101168 (acpi_tables) at level 0x60001, flags 0x1 [00000.000] INIT: cpu 0, calling hook 0xffffffff80103a80 (display_memtype) at level 0x60001, flags 0x1 [00000.000] INIT: cpu 0, calling hook 0xffffffff8010206c (hpet) at level 0x60002, flags 0x1 [00000.000] INIT: cpu 0, calling hook 0xffffffff801023a8 (apic) at level 0x60002, flags 0x1 [00000.000] x2APIC enabled [00000.000] INIT: cpu 0, calling hook 0xffffffff801065f0 (timer) at level 0x60003, flags 0x1 [00000.000] pvclock: Clocksource is stable [00000.000] HPET frequency: 100000 ticks/ms [00000.000] pvclock: Fetching TSC frequency [00000.000] TSC frequency: 2593992 ticks/ms [00000.319] timer features: constant_tsc 1 invariant_tsc 1 tsc_deadline1 [00000.319] Using TSC as wallclock [00000.319] initializing kernel [00000.319] initializing mp [00000.319] initializing threads [00000.319] initializing timers [00000.319] INIT: cpu 0, calling hook 0xffffffff80134adc (debuglog) at level 0x7ffff, flags 0x1 [00000.319] INIT: cpu 0, calling hook 0xffffffff80185728 (thread_set_priority_experiment) at level 0x7ffff, flags 0x1 [00000.319] thread set priority experiment is : ENABLED [00000.319] INIT: cpu 0, calling hook 0xffffffff80198264 (global_prng_thread_safe) at level 0x7ffff, flags 0x1 [00000.319] creating bootstrap completion thread [00000.319] top of bootstrap2() [00000.319] INIT: cpu 0, calling hook 0xffffffff8012ad60 (dpc) at level0x80000, flags 0x1 [00000.319] INIT: cpu 0, calling hook 0xffffffff8014cb54 (libobject) atlevel 0x80000, flags 0x1 [00000.319] OOM: started thread [00000.319] Processor Model Info: type 0 family 0x6 model 0xf stepping 0x1 [00000.319] display_family 0x6 display_model 0x4f [00000.319] Vendor: Intel [00000.319] Microarch: Broadwell [00000.319] F/M/S: 6/4f/1 [00000.319] Brand: Intel(R) Xeon(R) CPU E5-2690 v4 @ 2.60GHz [00000.319] Features: fpu sse sse2 sse3 ssse3 sse4.1 sse4.2 mmx avx avx2 fxsr pcid xsave aesni clflush [00000.319] fsgsbase tsc_adj smep smap erms rdrand rdseed syscall nx huge rdtscp invar_tsc tsc_deadline [00000.319] x2apic hypervisor [00000.319] x86_perfmon_have_mchbar_data:385: perfmon: unsupported pci device: 0x8086.0x29c0 [00000.319] initializing platform [00000.319] cpu topology: [00000.319] 0: apic id 0x0 package 0 node 0 core 0 smt 0 BSP [00000.319] 1: apic id 0x1 package 1 node 0 core 0 smt 0 [00000.319] 2: apic id 0x2 package 2 node 0 core 0 smt 0 [00000.319] 3: apic id 0x3 package 3 node 0 core 0 smt 0 [00000.319] Found 4 cpus [00000.319] booting apic ids: 0x1 0x2 0x3 [00000.329] entering scheduler on cpu 2 [00000.329] entering scheduler on cpu 3 [00000.329] entering scheduler on cpu 1 [00000.330] smbios: manufacturer="QEMU" product="Standard PC (Q35 + ICH9, 2009)" [00000.330] initializing target [00000.330] INIT: cpu 0, calling hook 0xffffffff80105618 (x86_pcie_init) at level 0xa0000, flags 0x1 [00000.330] moving to last init level [00000.330] INIT: cpu 0, calling hook 0xffffffff8013c174 (ktrace) at level 0xc0000, flags 0x1 [00000.341] ktrace: buffer at 0xffffff9812e30000 (33554432 bytes) [00000.341] INIT: cpu 0, calling hook 0xffffffff801409c4 (userboot) at level 0xc0000, flags 0x1 [00000.341] userboot: ramdisk 0x3cb000 @ 0xffffff80002ad000 [00000.342] userboot: userboot rodata 0 @ [0x55e94983e000,0x55e949841000) [00000.342] userboot: userboot code 0x3000 @ [0x55e949841000,0x55e94984c000) [00000.342] userboot: vdso/full rodata 0 @ [0x55e94984c000,0x55e949852000) [00000.342] userboot: vdso/full code 0x6000 @ [0x55e949852000,0x55e949853000) [00000.342] userboot: entry point @ 0x55e949841b50 [00000.342] INIT: cpu 0, calling hook 0xffffffff80197724 (kernel_shell)at level 0xc0000, flags 0x1 [00000.342] userboot: option "/usr/local/google/home/stephanstross/chromium/src/third_party/fuchsia-sdk/sdk/target/x86_64/zircon.bin=" [00000.342] userboot: option "devmgr.epoch=1528486548" [00000.342] userboot: option "zircon.nodename=fcaebea1-c966-4192-98e8-e6f5acb7e639" [00000.342] userboot: option "TERM=dumb" [00000.342] userboot: option "devmgr.require-system=true" [00000.342] userboot: option "zircon.system.blob-init=/blob/c101562d2dea5753b042595dfafa35ebdf6406876c04273165725f078df22c85" [00000.342] userboot: option "zircon.system.blob-init-arg=e876bf615c115af63b487af2960d8adae1eae56cef6373a570bb2fb7d9fd974b" [00000.357] userboot: searching bootfs for 'bin/devmgr' [00000.358] userboot: 'bin/devmgr' has PT_INTERP "lib/ld.so.1" [00000.358] userboot: searching bootfs for 'lib/ld.so.1' [00000.358] userboot: userboot: loaded lib/ld.so.1 at 0x4d6e9b4df000, entry point 0x4d6e9b56bec4 [00000.358] userboot: userboot: loaded vDSO at 0x53200c8fe000, entry point 0x0 [00000.358] userboot: process bin/devmgr started. [00000.358] userboot: waiting for loader-service requests... [00000.358] userboot: searching bootfs for 'lib/libasync-default.so' [00000.358] userboot: searching bootfs for 'lib/liblaunchpad.so' [00000.358] userboot: searching bootfs for 'lib/libfdio.so' [00000.358] {{{reset}}} [00000.358] {{{module:0:<application>:elf:4d815fe4bdd7c32ca109c9a833fbbdfc3955bfe6}}} [00000.358] {{{mmap:0x1eee3cf5e000:0x12000:load:0:rx:0}}} [00000.358] {{{mmap:0x1eee3cf70000:0x2000:load:0:rw:0x12000}}} [00000.358] dso: id=4d815fe4bdd7c32ca109c9a833fbbdfc3955bfe6 base=0x00001eee3cf5e000 name=<application> [00000.358] {{{module:0x3:libasync-default.so:elf:e770685a830911e0c40ea169ca6c80cbd6cc119c}}} [00000.358] {{{mmap:0x2aca88ca0000:0x1000:load:0x3:rx:0}}} [00000.358] {{{mmap:0x2aca88ca1000:0x1000:load:0x3:rw:0x1000}}} [00000.358] dso: id=e770685a830911e0c40ea169ca6c80cbd6cc119c base=0x00002aca88ca0000 name=libasync-default.so [00000.358] {{{module:0x4:liblaunchpad.so:elf:8f0b931e7dfb8820e57ecc153d7ba9608050d5a9}}} [00000.358] {{{mmap:0x69e515bdb000:0x7000:load:0x4:rx:0}}} [00000.358] {{{mmap:0x69e515be2000:0x2000:load:0x4:rw:0x7000}}} [00000.358] dso: id=8f0b931e7dfb8820e57ecc153d7ba9608050d5a9 base=0x000069e515bdb000 name=liblaunchpad.so [00000.358] {{{module:0x5:libfdio.so:elf:c3f0bed8493717a23b789e62fafe84e64f57e491}}} [00000.358] {{{mmap:0xe2228e33000:0x23000:load:0x5:rx:0}}} [00000.358] {{{mmap:0xe2228e57000:0x3000:load:0x5:rw:0x24000}}} [00000.358] dso: id=c3f0bed8493717a23b789e62fafe84e64f57e491 base=0x00000e2228e33000 name=libfdio.so [00000.358] {{{module:0x2:<vDSO>:elf:6c6bf49fafb6f79c5a7487c3184ad9d7779ef541}}} [00000.358] {{{mmap:0x53200c8fe000:0x6000:load:0x2:r:0}}} [00000.358] {{{mmap:0x53200c904000:0x1000:load:0x2:rx:0x6000}}} [00000.358] dso: id=6c6bf49fafb6f79c5a7487c3184ad9d7779ef541 base=0x000053200c8fe000 name=<vDSO> [00000.358] {{{module:0x1:libc.so:elf:6f84aeabef70f54523ac1b5f8c618c0b03013f25}}} [00000.358] {{{mmap:0x4d6e9b4df000:0xd5000:load:0x1:rx:0}}} [00000.358] {{{mmap:0x4d6e9b5b4000:0x6000:load:0x1:rw:0xd5000}}} [00000.358] dso: id=6f84aeabef70f54523ac1b5f8c618c0b03013f25 base=0x00004d6e9b4df000 name=libc.so [00000.359] devmgr: main() [00000.359] userboot: loader-service channel peer closed [00000.359] devmgr: init [00000.359] userboot: finished! [00000.359] coordinator_init() [00000.359] devmgr: vfs init [00000.360] devmgr: launch /boot/bin/fshost (fshost) OK [00000.361] fshost: started. [00000.363] cmdline: /usr/local/google/home/stephanstross/chromium/src/third_party/fuchsia-sdk/sdk/target/x86_64/zircon.bin= [00000.363] cmdline: devmgr.epoch=1528486548 [00000.363] cmdline: zircon.nodename=fcaebea1-c966-4192-98e8-e6f5acb7e639 [00000.363] cmdline: TERM=dumb [00000.363] cmdline: devmgr.require-system=true [00000.363] cmdline: zircon.system.blob-init=/blob/c101562d2dea5753b042595dfafa35ebdf6406876c04273165725f078df22c85 [00000.363] cmdline: zircon.system.blob-init-arg=e876bf615c115af63b487af2960d8adae1eae56cef6373a570bb2fb7d9fd974b [00000.363] devmgr: shell startup [00000.363] devmgr: coordinator() [00000.364] devmgr: launch /boot/bin/crashsvc (crashsvc) OK [00000.368] devmgr: launch /boot/bin/netsvc (netsvc) OK [00000.372] devmgr: launch /boot/bin/virtual-console (virtual-console) OK [00000.378] devcoord: launch devhost 'devhost:sys': pid=1730 [00000.379] devcoord: launch devhost 'devhost:test': pid=1764 [00000.379] devcoord: full system required, ignoring fallback drivers until /system is loaded [00000.380] devcoord: launch devhost 'devhost:root': pid=1816 [00000.384] devcoord: launch devhost 'devhost:misc': pid=1863 [00000.397] usb_virtual_bus_bind [00000.473] AllocateBarLocked:572: Failed to preserve device 00:01.0's PFMMIO window [0xfd000000, 0xfdffffff] Attempting to re-allocate. [00000.474] AllocateBarLocked:572: Failed to preserve device 00:02.0's PFMMIO window [0xfe000000, 0xfe003fff] Attempting to re-allocate. [00000.475] AllocateBarLocked:572: Failed to preserve device 00:03.0's PFMMIO window [0xfe004000, 0xfe007fff] Attempting to re-allocate. [00000.477] acpi: published device pci(0x23345bd26600), parent=proxy(0x23345bd3a000), handle=0x23345bd043c0 [00000.477] acpi: failed to get PCI base bus number for device 'PCI0' (acpi_status 5) [00000.477] acpi: published device rtc(0x23345bd265c0), parent=acpi(0x23345bd3a180), handle=0x23345bd04870 [00000.477] acpi: published device i8042(0x23345bd26580), parent=acpi(0x23345bd3a180), handle=0x23345bd04900 [00000.478] IntelPT: No PT support [00000.478] mtrace_ipm_control:34: action 0, options 0x0, arg 0x463d4d04b20, size 0x20 [00000.478] ipm_init_once: No PM support [00000.479] devcoord: launch devhost 'devhost:pci#1:1234:1111': pid=2198 [00000.480] devcoord: launch devhost 'devhost:pci#2:1af4:1001': pid=2236 [00000.482] devcoord: launch devhost 'devhost:pci#3:1af4:1001': pid=2300 [00000.484] devcoord: launch devhost 'devhost:pci#4:8086:100e': pid=2358 [00000.485] devcoord: launch devhost 'devhost:pci#6:8086:2922': pid=2419 [00000.487] devhost: WARNING: driver '/boot/driver/pc-ps2.so' did not add device in bind() [00000.488] i8042 device 0xab 0x41 [00000.493] bochs_vbe: initialized display, 1024 x 768 (stride=1024 format=00020001) [00000.501] eth: using legacy irq mode [00000.502] devmgr: launch /boot/bin/sh (sh:console) OK [00000.503] eth: mac: 52:54:00:63:5e:7b [00000.504] eth: iomem @0x13d4b1e37000 (phys 33cc000) [00000.506] eth: intel-ethernet online [00000.507] ahci: using MSI interrupt [00000.509] netifc: ? /dev/class/ethernet/000 [00000.510] netifc: create 512 eth buffers [00000.511] i8042 device 0x00 [00000.513] macaddr: 52:54:00:63:5e:7b [00000.513] ip6addr: fe80::5054:4d:fe63:5e7b [00000.513] snmaddr: ff02::1:ff63:5e7b [00000.513] netsvc: using /dev/class/ethernet/000 [00000.514] netsvc: nodename='fcaebea1-c966-4192-98e8-e6f5acb7e639' [00000.514] netsvc: start [00000.515] devmgr: /dev/class/block/000: FVM? [00000.516] devcoord: dc_bind_device() '/boot/driver/fvm.so' [00000.516] hid: boot mouse hack for "hid-device-002": report count (1->1), inp sz (24->24), out sz (0->0), feat sz (0->0) [00000.523] devmgr: /dev/class/block/001: FVM? [00000.523] devcoord: dc_bind_device() '/boot/driver/fvm.so' [00000.525] devmgr: launch /boot/bin/blobfs (blobfs:/blob) OK [00000.599] vc: new input device /dev/class/input/000 [00000.599] vc: new input device /dev/class/input/001 [00000.638] devmgr: launch /fs/blob/c101562d2dea5753b042595dfafa35ebdf6406876c04273165725f078df22c85 (pkgfs) OK [00000.645] pkgsvr: 2018/06/08 19:35:50 system: will be served from e876bf615c115af63b487af2960d8adae1eae56cef6373a570bb2fb7d9fd974b [00000.645] pkgsvr: 2018/06/08 19:35:50 pkgfs serving index /data/pkgfs_index from blobfs /blob [00000.646] devcoord: fallback driver 'intel_disp' is available [00000.646] devcoord: driver 'intel_disp' added [00000.647] devmgr: mounting minfs [00000.648] devmgr: launch /boot/bin/minfs (minfs:/data) OK [00000.653] devmgr: launch /system/bin/appmgr (appmgr) OK [00000.710] [ERROR:garnet/bin/appmgr/root_loader.cc(71)] Could not loadurl: file://cobalt_system_metrics [00000.710] [ERROR:garnet/bin/appmgr/root_loader.cc(71)] Could not loadurl: file://netconnector [00000.711] [ERROR:garnet/bin/appmgr/root_loader.cc(71)] Could not loadurl: file://network_time [00000.715] [ERROR:garnet/bin/appmgr/root_loader.cc(71)] Could not loadurl: file://wlanstack [00000.774] [ERROR:garnet/bin/sysmgr/app.cc(146)] Singleton wlanstack died [00000.780] netstack: started [00000.780] netstack: socket dispatcher started [00000.781] netstack: watching for ethernet devices [00000.782] netstack: linkaddr: 52:54:00:63:5e:7b [00000.782] netstack: NIC 2 added using ethernet device "/dev/class/ethernet/000" [00000.782] netstack: NIC 2: ipv6addr: fe80::5054:ff:fe63:5e7b [00000.784] netstack: NIC 2: DHCP acquired IP 192.168.3.9 for 24h0m0s [00000.784] netstack: NIC 2: DNS servers: [192.168.3.3] [00000.789] [INFO:main.cc(35)] Trace Manager starting with config: /pkg/data/tracing.config [00006.612] Could not load host key: /system/data/ssh/ssh_host_ed25519_key [00006.617] netstack: convSockOpt: TODO IPPROTO_IP optname=4 [00008.176] netstack: convSockOpt: TODO IPPROTO_IP optname=1 2018-06-08 12:36:01,984:INFO:root:Installing package. [00011.397] pkgsvr: 2018/06/08 19:36:00 pkgfs: importing package from "ceed5ef9c9557cda133275cd6087a99ad44586c624f3d58c316df8b38b3f530b" [00011.417] pkgsvr: 2018/06/08 19:36:00 pkgfs: blob already present for{net_perftests 0}: "3fef51a772babc3d056d9d0152f813485fcac86f8b36464ed2ca42c345f5e16e" [00011.417] pkgsvr: 2018/06/08 19:36:00 pkgfs: blob already present for{net_perftests 0}: "fae5d793001067ae90c1ce93288dab735916889efeaec84d32040dbb154b4407" [00011.417] pkgsvr: 2018/06/08 19:36:00 pkgfs: blob already present for{net_perftests 0}: "3fef51a772babc3d056d9d0152f813485fcac86f8b36464ed2ca42c345f5e16e" [00011.417] pkgsvr: 2018/06/08 19:36:00 pkgfs: blob already present for{net_perftests 0}: "4037f959a943be3051865ed7571c5dc5afc959d98f7e1917bb946034682d4c54" [00011.417] pkgsvr: 2018/06/08 19:36:00 pkgfs: blob already present for{net_perftests 0}: "5150f1d32c6decda72656e53350330776b7b6a9c41bfc3899f39da8ba17bdb41" [00011.423] pkgsvr: 2018/06/08 19:36:00 pkgfs: asking amber to fetch 2290 blobs for {net_perftests 0} [00011.423] 2018/06/08 19:36:00 meta.far written, starting blobs 2018-06-08 12:36:03,461:INFO:root:Running application. [00012.820] pkgsvr: 2018/06/08 19:36:02 pkgfs:unsupported(/packages/net_perftests/0): dir unlink "app.log" Note: Google Test filter = DiskCachePerfTest.CacheBackendPerformance [==========] Running 1 test from 1 test case. [----------] Global test environment set-up. [----------] 1 test from DiskCachePerfTest [ RUN ] DiskCachePerfTest.CacheBackendPerformance [76650:133119661:0608/193602.382781:12869454:ERROR:disk_cache_perftest.cc(423)] Using cache at:/tmp/.org.chromium.Chromium.iiAGbk Write disk cache entries 12044.1 ms [76650:133119661:0608/193615.212941:25699604:ERROR:test_file_util_posix.cc(85)] Not implemented reached in bool base::EvictFileFromSystemCache(const base::FilePath &) ../../net/disk_cache/disk_cache_perftest.cc:406: Failure Value of: base::EvictFileFromSystemCache(file_path) Actual: false Expected: true [00025.700] devmgr: analyzer_starter: launching for exception type 0x108 Stack trace: [00025.701] devmgr: launch /boot/bin/crashanalyzer (analyzer) OK #00: testing::internal::UnitTestImpl::CurrentOsStackTraceExceptTop(int)at gtest.cc:? #01: testing::internal::AssertHelper::operator=(testing::Message const&) const at gtest.cc:? #02: (anonymous namespace)::DiskCachePerfTest::ResetAndEvictSystemDiskCache() at disk_cache_perftest.cc:? #03: (anonymous namespace)::DiskCachePerfTest::CacheBackendPerformance() at disk_cache_perftest.cc:? [00025.702] <== fatal exception: process net_perftests[76650] thread initial-thread[76663] [00025.702] <== fatal page fault, PC at 0x7f51c7d0587d [00025.702] CS: 0 RIP: 0x7f51c7d0587d EFL: 0x10206 CR2: 0 [00025.703] RAX: 0xbc86 RBX: 0x47d7f3aef0c0 RCX: 0x58 RDX: 0x7f51c7d05cd0 [00025.703] RSI: 0x47d7f3aef0c0 RDI: 0 RBP: 0x47ad608911a8 RSP: 0x3e52cc8ada20 [00025.703] R8: 0xffffffffffffffff R9: 0x3e52cc8ad9b0 R10: 0x8000 R11: 0x20000000000000 [00025.703] R12: 0x3e52cc8adae8 R13: 0x3e52cc8adbe8 R14: 0x3e52cc8ada30 R15: 0x3e52cc8ada38 [00025.703] errc: 0x4 2018-06-08 12:36:16,382:WARNING:root:Process exited with status code 255. 2018-06-08 12:36:16,382:INFO:root:Terminating kernel log reader. 2018-06-08 12:36:16,382:INFO:root:Removing package source from device. 2018-06-08 12:36:16,400:INFO:root:Shutting down QEMU.
,
Jun 8 2018
Looks like we just nit Fuchsia-specific implementation of base::EvictFileFromSystemCache(). |
|
►
Sign in to add a comment |
|
Comment 1 by sergeyu@chromium.org
, Jun 8 2018