nvsl / linux-nova

NOVA is a log-structured file system designed for byte-addressable non-volatile memories, developed at the University of California, San Diego.

NOVA: NOn-Volatile memory Accelerated log-structured file system

Linux versions supported

5.1 (current master), 5.0, 4.19, 4.18, 4.14, 4.13. Checkout each branch if you are interested.

Description

NOVA's goal is to provide a high-performance, full-featured, production-ready file system tailored for byte-addressable non-volatile memories (e.g., NVDIMMs and Intel's soon-to-be-released 3DXpoint DIMMs). It combines design elements from many other file systems to provide a combination of high-performance, strong consistency guarantees, and comprehensive data protection. NOVA support DAX-style mmap and making DAX performs well is a first-order priority in NOVA's design. NOVA was developed by the Non-Volatile Systems Laboratory in the Computer Science and Engineering Department at the University of California, San Diego.

NOVA is primarily a log-structured file system, but rather than maintain a single global log for the entire file system, it maintains separate logs for each file (inode). NOVA breaks the logs into 4KB pages, they need not be contiguous in memory. The logs only contain metadata.

File data pages reside outside the log, and log entries for write operations point to data pages they modify. File modification uses copy-on-write (COW) to provide atomic file updates.

For file operations that involve multiple inodes, NOVA use small, fixed-sized redo logs to atomically append log entries to the logs of the inodes involned.

This structure keeps logs small and make garbage collection very fast. It also enables enormous parallelism during recovery from an unclean unmount, since threads can scan logs in parallel.

NOVA replicates and checksums all metadata structures and protects file data with RAID-4-style parity. It supports checkpoints to facilitate backups.

This repository contains a version of the mainline kernel with NOVA added. You can check the current version by looking at the first lines of the Makefile.

A more thorough discussion of NOVA's design is avaialable in these two papers:

NOVA: A Log-structured File system for Hybrid Volatile/Non-volatile Main Memories PDF
Jian Xu and Steven Swanson
Published in FAST 2016

Hardening the NOVA File System PDF
UCSD-CSE Techreport CS2017-1018 Jian Xu, Lu Zhang, Amirsaman Memaripour, Akshatha Gangadharaiah, Amit Borase, Tamires Brito Da Silva, Andy Rudoff, Steven Swanson

Read on for further details about NOVA's overall design and its current status

Compatibilty with Other File Systems

NOVA aims to be compatible with other Linux file systems. To help verify that it achieves this we run several test suites against NOVA each night.

• The latest version of XFSTests. (Current failures)
• The (Linux testing project)(https://linux-test-project.github.io/) file system tests.
• The (fstest POSIX test suite)POSIXtest.

Currently, nearly all of these tests pass for the master branch, and we have run complex programs on NOVA. There are, of course, many bugs left to fix.

NOVA uses the standard PMEM kernel interfaces for accessing and managing persistent memory.

Atomicity

By default, NOVA makes all metadata and file data operations atomic.

Strong atomicity guarantees make it easier to build reliable applications on NOVA, and NOVA can provide these guarantees with sacrificing much performance because NVDIMMs support very fast random access.

NOVA also supports "unsafe data" and "unsafe metadata" modes that improve performance in some cases and allows for non-atomic updates of file data and metadata, respectively.

Data Protection

NOVA aims to protect data against both misdirected writes in the kernel (which can easily "scribble" over the contents of an NVDIMM) as well as media errors.

NOVA protects all of its metadata data structures with a combination of replication and checksums. It protects file data using RAID-5 style parity.

NOVA can detects data corruption by verifying checksums on each access and by catching and handling machine check exceptions (MCEs) that arise when the system's memory controller detects at uncorrectable media error.

We use a fault injection tool that allows testing of these recovery mechanisms.

To facilitate backups, NOVA can take snapshots of the current filesystem state that can be mounted read-only while the current file system is mounted read-write.

The tech report list above describes the design of NOVA's data protection system in detail.

DAX Support

Supporting DAX efficiently is a core feature of NOVA and one of the challenges in designing NOVA is reconciling DAX support which aims to avoid file system intervention when file data changes, and other features that require such intervention.

NOVA's philosophy with respect to DAX is that when a program uses DAX mmap to to modify a file, the program must take full responsibility for that data and NOVA must ensure that the memory will behave as expected. At other times, the file system provides protection. This approach has several implications:

1. Implementing msync() in user space works fine.

2. While a file is mmap'd, it is not protected by NOVA's RAID-style parity mechanism, because protecting it would be too expensive. When the file is unmapped and/or during file system recovery, protection is restored.

3. The snapshot mechanism must be careful about the order in which in adds pages to the file's snapshot image.

Performance

The research paper and technical report referenced above compare NOVA's performance to other file systems. In almost all cases, NOVA outperforms other DAX-enabled file systems. A notable exception is sub-page updates which incur COW overheads for the entire page.

The technical report also illustrates the trade-offs between our protection mechanisms and performance.

Gaps, Missing Features, and Development Status

Although NOVA is a fully-functional file system, there is still much work left to be done. In particular, (at least) the following items are currently missing:

1. There is no mkfs or fsk utility (mount takes -o init to create a NOVA file system)
2. NOVA doesn't scrub data to prevent corruption from accumulating in infrequently accessed data.
3. NOVA doesn't read bad block information on mount and attempt recovery of the effected data.
4. NOVA only works on x86-64 kernels.
5. NOVA does not currently support extended attributes or ACL.
6. NOVA does not currently prevent writes to mounted snapshots.
7. Using write() to modify pages that are mmap'd is not supported.
8. NOVA deoesn't provide quota support.
9. Moving NOVA file systems between machines with different numbers of CPUs does not work.
10. Remounting a NOVA file system with different mount options may fail.

None of these are fundamental limitations of NOVA's design. Additional bugs and issues are here.

NOVA is complete and robust enough to run a range of complex applications, but it is not yet ready for production use. Our current focus is on adding a few missing features list above and finding/fixing bugs.

Building and Using NOVA

This repo contains a version of the Linux with NOVA included. You should be able to build and install it just as you would the mainline Linux source.

Building NOVA

To build NOVA, build the kernel with LIBNVDIMM (CONFIG_LIBNVDIMM), PMEM (CONFIG_BLK_DEV_PMEM), DAX (CONFIG_FS_DAX) and NOVA (CONFIG_NOVA_FS) support. Install as usual. (When running make menuconfig, you can find those options under the Device Drivers and File Systems sections, respectively.)

Documentation/filesystems/nova.txt provides more detailed instructions on building and using NOVA.

Hacking and Contributing

The NOVA source code is almost completely contains in the fs/nova directory. The execptions are some small changes in the kernel's memory management system to support checkpointing.

Documentation/filesystems/nova.txt describes the internals of Nova in more detail.

If you find bugs, please report them.

If you have other questions or suggestions you can contact the NOVA developers at [email protected].

linux-nova's Issues

Add mkfs

From @stevenjswanson on May 8, 2017 21:59

Copied from original issue: NVSL/nova-dev#14

Cleanup etc. from reading the f2fs LKML discussion

https://lkml.org/lkml/2012/10/22/664

• Add buffer before superblock begin? (https://lkml.org/lkml/2012/10/26/246)
• Should we have a volume serial number?
• comments on every data structure.
• move userspace visible data structures (e.g., for fsk) to include/linux
• add magic number. Put it in magic.h
• explain magical constants.
• what belongs in /sys/fs vs debugfs vs. /proc/

XFStests generic/313: fails for unsafe metadata

generic/313 4s ... - output mismatch (see /home/swanson/nova-testscripts/nova-ci/xfstests/xfstests/results//generic/313.out.bad)
    --- tests/generic/313.out   2017-07-19 18:38:10.810060693 +0000
    +++ /home/swanson/nova-testscripts/nova-ci/xfstests/xfstests/results//generic/313.out.bad   2017-07-20 07:18:44.006231196 +0000
    @@ -1,2 +1,4 @@
     QA output created by 313
     Silence is golden
    +ctime not updated after ftruncate
    +mtime not updated after ftruncate
    ...
    (Run 'diff -u tests/generic/313.out /home/swanson/nova-testscripts/nova-ci/xfstests/xfstests/results//generic/313.out.bad'  to see the entire diff)

XFSTests generic/258 failure: negative timestamps wrap

FSTYP -- NOVA
PLATFORM -- Linux/x86_64 instance-1 4.10.0-rc8-nova
MKFS_OPTIONS -- /dev/pmem1
MOUNT_OPTIONS -- /dev/pmem1 /mnt/scratch

generic/258 [failed, exit status 1] - output mismatch (see /home/nova-ci/nova-testscripts/nova-ci/xfstests/xfstests/results//generic/258.out.bad)
--- tests/generic/258.out 2017-06-29 19:17:54.640783343 +0000
+++ /home/nova-ci/nova-testscripts/nova-ci/xfstests/xfstests/results//generic/258.out.bad 2017-06-29 21:21:53.052662461 +0000
@@ -3,3 +3,6 @@
Testing for negative seconds since epoch
Remounting to flush cache
Testing for negative seconds since epoch
+Timestamp wrapped: 3979351756
+Timestamp wrapped
+(see /home/nova-ci/nova-testscripts/nova-ci/xfstests/xfstests/results//generic/258.full for details)
...
(Run 'diff -u tests/generic/258.out /home/nova-ci/nova-testscripts/nova-ci/xfstests/xfstests/results//generic/258.out.bad' to see the entire diff)
Ran: generic/258
Failures: generic/258
Failed 1 of 1 tests

Snapshot atime

From @Andiry on August 4, 2016 20:37

Snapshot atime

Copied from original issue: NVSL/nova-dev#1

Crash during fxbench

From @stevenjswanson on June 13, 2017 23:2

I'm getting a consistent crash while running fxbench on the test machine.

commit f5ccaacfda12289ace1f53109ad3104bbc43e3ca

dmesg:

[ 938.940146] nova: Current epoch id: 0
[ 938.940205] nova: nova_save_inode_list_to_log: 18 inode nodes, pi head 0x333835000, tail 0x333835120
[ 938.940269] nova: nova_save_blocknode_mappings_to_log: 279 blocknodes, 2 log pages, pi head 0x333836000, tail 0x333837190
[ 938.949153] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 938.949155] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 938.949259] nova: Start NOVA snapshot cleaner thread.
[ 938.949267] nova: Running snapshot cleaner thread
[ 938.949294] nova: nova_init_inode_list_from_inode: 18 inode nodes
[ 938.949296] nova: Recovered 0 snapshots, latest epoch ID 0
[ 938.949296] nova: NOVA: Normal shutdown
[ 938.951513] nova: Current epoch id: 0
[ 938.968640] run fstests generic/311 at 2017-06-13 21:24:57
[ 939.127874] run fstests generic/312 at 2017-06-13 21:24:57
[ 939.286753] run fstests generic/313 at 2017-06-13 21:24:58
[ 943.482926] nova: Current epoch id: 0
[ 943.482978] nova: nova_save_inode_list_to_log: 18 inode nodes, pi head 0x333835000, tail 0x333835120
[ 943.483038] nova: nova_save_blocknode_mappings_to_log: 279 blocknodes, 2 log pages, pi head 0x333836000, tail 0x333837190
[ 943.491356] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 943.491359] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 943.491449] nova: Start NOVA snapshot cleaner thread.
[ 943.491455] nova: Running snapshot cleaner thread
[ 943.491483] nova: nova_init_inode_list_from_inode: 18 inode nodes
[ 943.491486] nova: Recovered 0 snapshots, latest epoch ID 0
[ 943.491486] nova: NOVA: Normal shutdown
[ 943.493635] nova: Current epoch id: 0
[ 943.510833] run fstests generic/314 at 2017-06-13 21:25:02
[ 943.706188] run fstests generic/315 at 2017-06-13 21:25:02
[ 943.887646] run fstests generic/316 at 2017-06-13 21:25:02
[ 944.069018] run fstests generic/317 at 2017-06-13 21:25:02
[ 944.246876] nova: Current epoch id: 0
[ 944.246960] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x2de65f000, tail 0x2de65f080
[ 944.246987] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x2de660000, tail 0x2de660390
[ 944.312210] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 944.312212] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 944.312326] nova: Start NOVA snapshot cleaner thread.
[ 944.312333] nova: Running snapshot cleaner thread
[ 944.312348] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 944.312350] nova: Recovered 0 snapshots, latest epoch ID 0
[ 944.312350] nova: NOVA: Normal shutdown
[ 944.315444] nova: Current epoch id: 0
[ 944.338880] nova: Current epoch id: 0
[ 944.338930] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0xe65e000, tail 0xe65e080
[ 944.338945] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0xe65f000, tail 0xe65f390
[ 944.344853] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 944.344855] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 944.344945] nova: Start NOVA snapshot cleaner thread.
[ 944.344959] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 944.344960] nova: Recovered 0 snapshots, latest epoch ID 0
[ 944.344961] nova: NOVA: Normal shutdown
[ 944.344980] nova: Running snapshot cleaner thread
[ 944.348049] nova: Current epoch id: 0
[ 944.386798] nova: Current epoch id: 0
[ 944.386843] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x176656000, tail 0x176656080
[ 944.386858] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x176657000, tail 0x176657380
[ 944.392985] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 944.392987] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 944.393121] nova: Start NOVA snapshot cleaner thread.
[ 944.393128] nova: Running snapshot cleaner thread
[ 944.393135] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 944.393137] nova: Recovered 0 snapshots, latest epoch ID 0
[ 944.393137] nova: NOVA: Normal shutdown
[ 944.396217] nova: Current epoch id: 0
[ 944.418799] nova: Current epoch id: 0
[ 944.418857] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1ee657000, tail 0x1ee657080
[ 944.418872] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x1ee658000, tail 0x1ee658390
[ 944.459280] run fstests generic/318 at 2017-06-13 21:25:03
[ 944.680721] run fstests generic/319 at 2017-06-13 21:25:03
[ 944.877109] run fstests generic/320 at 2017-06-13 21:25:03
[ 945.077249] run fstests generic/321 at 2017-06-13 21:25:03
[ 945.245400] run fstests generic/322 at 2017-06-13 21:25:04
[ 945.406189] run fstests generic/323 at 2017-06-13 21:25:04
[ 1065.919146] nova: Current epoch id: 0
[ 1065.919204] nova: nova_save_inode_list_to_log: 17 inode nodes, pi head 0xb37c1000, tail 0xb37c1110
[ 1065.919262] nova: nova_save_blocknode_mappings_to_log: 266 blocknodes, 2 log pages, pi head 0xb37c3000, tail 0xb37c40c0
[ 1065.928506] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 1065.928508] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1065.928591] nova: Start NOVA snapshot cleaner thread.
[ 1065.928599] nova: Running snapshot cleaner thread
[ 1065.928625] nova: nova_init_inode_list_from_inode: 17 inode nodes
[ 1065.928628] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1065.928628] nova: NOVA: Normal shutdown
[ 1065.930833] nova: Current epoch id: 0
[ 1065.948750] run fstests generic/324 at 2017-06-13 21:27:04
[ 1066.136179] run fstests generic/325 at 2017-06-13 21:27:04
[ 1066.321253] run fstests generic/326 at 2017-06-13 21:27:05
[ 1066.511037] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1066.511039] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1066.511108] nova: Start NOVA snapshot cleaner thread.
[ 1066.511114] nova: Running snapshot cleaner thread
[ 1066.511122] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1066.511125] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1066.511125] nova: NOVA: Normal shutdown
[ 1066.514297] nova: Current epoch id: 0
[ 1066.546957] nova: Current epoch id: 0
[ 1066.547003] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x176656000, tail 0x176656080
[ 1066.547019] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x176657000, tail 0x176657380
[ 1066.552817] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1066.552818] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1066.552951] nova: Start NOVA snapshot cleaner thread.
[ 1066.552960] nova: Running snapshot cleaner thread
[ 1066.552964] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1066.552966] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1066.552967] nova: NOVA: Normal shutdown
[ 1066.556085] nova: Current epoch id: 0
[ 1066.582945] nova: Current epoch id: 0
[ 1066.583019] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x356669000, tail 0x356669080
[ 1066.583040] nova: nova_save_blocknode_mappings_to_log: 55 blocknodes, 1 log pages, pi head 0x35666a000, tail 0x35666a370
[ 1066.605550] run fstests generic/327 at 2017-06-13 21:27:05
[ 1066.785492] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1066.785495] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1066.785617] nova: Start NOVA snapshot cleaner thread.
[ 1066.785628] nova: Running snapshot cleaner thread
[ 1066.785639] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1066.785642] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1066.785643] nova: NOVA: Normal shutdown
[ 1066.789768] nova: Current epoch id: 0
[ 1066.814976] nova: Current epoch id: 0
[ 1066.815046] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x356656000, tail 0x356656080
[ 1066.815068] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x356657000, tail 0x356657390
[ 1066.821008] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1066.821010] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1066.821110] nova: Start NOVA snapshot cleaner thread.
[ 1066.821118] nova: Running snapshot cleaner thread
[ 1066.821129] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1066.821132] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1066.821133] nova: NOVA: Normal shutdown
[ 1066.824722] nova: Current epoch id: 0
[ 1066.850850] nova: Current epoch id: 0
[ 1066.850892] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0xe65e000, tail 0xe65e080
[ 1066.850907] nova: nova_save_blocknode_mappings_to_log: 55 blocknodes, 1 log pages, pi head 0xe65f000, tail 0xe65f370
[ 1066.873287] run fstests generic/328 at 2017-06-13 21:27:05
[ 1067.056916] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1067.056920] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1067.057021] nova: Start NOVA snapshot cleaner thread.
[ 1067.057030] nova: Running snapshot cleaner thread
[ 1067.057050] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1067.057053] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1067.057054] nova: NOVA: Normal shutdown
[ 1067.060511] nova: Current epoch id: 0
[ 1067.087064] nova: Current epoch id: 0
[ 1067.087124] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x356656000, tail 0x356656080
[ 1067.087150] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x356657000, tail 0x356657390
[ 1067.092794] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1067.092797] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1067.092945] nova: Start NOVA snapshot cleaner thread.
[ 1067.092960] nova: Running snapshot cleaner thread
[ 1067.092961] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1067.092963] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1067.092964] nova: NOVA: Normal shutdown
[ 1067.096110] nova: Current epoch id: 0
[ 1067.126872] nova: Current epoch id: 0
[ 1067.126938] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1ee657000, tail 0x1ee657080
[ 1067.126952] nova: nova_save_blocknode_mappings_to_log: 51 blocknodes, 1 log pages, pi head 0x1ee658000, tail 0x1ee658330
[ 1067.148881] run fstests generic/329 at 2017-06-13 21:27:05
[ 1067.397610] run fstests generic/330 at 2017-06-13 21:27:06
[ 1067.576008] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1067.576010] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1067.576136] nova: Start NOVA snapshot cleaner thread.
[ 1067.576144] nova: Running snapshot cleaner thread
[ 1067.576155] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1067.576157] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1067.576157] nova: NOVA: Normal shutdown
[ 1067.579252] nova: Current epoch id: 0
[ 1067.614897] nova: Current epoch id: 0
[ 1067.614951] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x2de65f000, tail 0x2de65f080
[ 1067.614966] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x2de660000, tail 0x2de660390
[ 1067.620483] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1067.620485] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1067.620646] nova: Start NOVA snapshot cleaner thread.
[ 1067.620651] nova: Running snapshot cleaner thread
[ 1067.620661] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1067.620663] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1067.620664] nova: NOVA: Normal shutdown
[ 1067.624021] nova: Current epoch id: 0
[ 1067.642863] nova: Current epoch id: 0
[ 1067.642910] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0xfe656000, tail 0xfe656080
[ 1067.642925] nova: nova_save_blocknode_mappings_to_log: 54 blocknodes, 1 log pages, pi head 0xfe658000, tail 0xfe658360
[ 1067.665110] run fstests generic/331 at 2017-06-13 21:27:06
[ 1067.843563] run fstests generic/332 at 2017-06-13 21:27:06
[ 1068.039758] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1068.039761] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1068.039859] nova: Start NOVA snapshot cleaner thread.
[ 1068.039867] nova: Running snapshot cleaner thread
[ 1068.039872] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1068.039874] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1068.039874] nova: NOVA: Normal shutdown
[ 1068.042975] nova: Current epoch id: 0
[ 1068.071052] nova: Current epoch id: 0
[ 1068.071125] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0xfe656000, tail 0xfe656080
[ 1068.071147] nova: nova_save_blocknode_mappings_to_log: 56 blocknodes, 1 log pages, pi head 0xfe658000, tail 0xfe658380
[ 1068.077578] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1068.077582] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1068.077667] nova: Start NOVA snapshot cleaner thread.
[ 1068.077675] nova: Running snapshot cleaner thread
[ 1068.077688] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1068.077692] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1068.077692] nova: NOVA: Normal shutdown
[ 1068.081128] nova: Current epoch id: 0
[ 1068.102863] nova: Current epoch id: 0
[ 1068.102910] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1ee657000, tail 0x1ee657080
[ 1068.102930] nova: nova_save_blocknode_mappings_to_log: 52 blocknodes, 1 log pages, pi head 0x1ee658000, tail 0x1ee658340
[ 1068.125787] run fstests generic/333 at 2017-06-13 21:27:06
[ 1068.319498] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1068.319500] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1068.319616] nova: Start NOVA snapshot cleaner thread.
[ 1068.319624] nova: Running snapshot cleaner thread
[ 1068.319629] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1068.319632] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1068.319632] nova: NOVA: Normal shutdown
[ 1068.322663] nova: Current epoch id: 0
[ 1068.346894] nova: Current epoch id: 0
[ 1068.346952] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0xe65e000, tail 0xe65e080
[ 1068.346966] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0xe65f000, tail 0xe65f390
[ 1068.352817] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1068.352819] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1068.352903] nova: Start NOVA snapshot cleaner thread.
[ 1068.352912] nova: Running snapshot cleaner thread
[ 1068.352916] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1068.352918] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1068.352919] nova: NOVA: Normal shutdown
[ 1068.356263] nova: Current epoch id: 0
[ 1068.378913] nova: Current epoch id: 0
[ 1068.378954] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x86656000, tail 0x86656080
[ 1068.378969] nova: nova_save_blocknode_mappings_to_log: 55 blocknodes, 1 log pages, pi head 0x86658000, tail 0x86658370
[ 1068.400231] run fstests generic/334 at 2017-06-13 21:27:07
[ 1068.592265] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1068.592267] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1068.592361] nova: Start NOVA snapshot cleaner thread.
[ 1068.592369] nova: Running snapshot cleaner thread
[ 1068.592378] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1068.592380] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1068.592380] nova: NOVA: Normal shutdown
[ 1068.595511] nova: Current epoch id: 0
[ 1068.614923] nova: Current epoch id: 0
[ 1068.614948] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x2de65f000, tail 0x2de65f080
[ 1068.614964] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x2de660000, tail 0x2de660390
[ 1068.620148] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1068.620172] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1068.620248] nova: Start NOVA snapshot cleaner thread.
[ 1068.620256] nova: Running snapshot cleaner thread
[ 1068.620261] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1068.620263] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1068.620263] nova: NOVA: Normal shutdown
[ 1068.623323] nova: Current epoch id: 0
[ 1068.650869] nova: Current epoch id: 0
[ 1068.650921] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0xe65e000, tail 0xe65e080
[ 1068.650936] nova: nova_save_blocknode_mappings_to_log: 55 blocknodes, 1 log pages, pi head 0xe65f000, tail 0xe65f370
[ 1068.671959] run fstests generic/335 at 2017-06-13 21:27:07
[ 1068.869682] run fstests generic/336 at 2017-06-13 21:27:07
[ 1069.045560] run fstests generic/337 at 2017-06-13 21:27:07
[ 1069.240938] run fstests generic/338 at 2017-06-13 21:27:08
[ 1069.416588] run fstests generic/339 at 2017-06-13 21:27:08
[ 1069.599025] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1069.599027] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1069.599103] nova: Start NOVA snapshot cleaner thread.
[ 1069.599111] nova: Running snapshot cleaner thread
[ 1069.599117] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1069.599119] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1069.599119] nova: NOVA: Normal shutdown
[ 1069.602230] nova: Current epoch id: 0
[ 1069.622894] nova: Current epoch id: 0
[ 1069.622945] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x176656000, tail 0x176656080
[ 1069.622961] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x176657000, tail 0x176657380
[ 1069.629093] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1069.629095] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1069.629175] nova: Start NOVA snapshot cleaner thread.
[ 1069.629184] nova: Running snapshot cleaner thread
[ 1069.629199] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1069.629202] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1069.629202] nova: NOVA: Normal shutdown
[ 1069.632320] nova: Current epoch id: 0
[ 1070.151657] nova: Current epoch id: 0
[ 1070.151782] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x86656000, tail 0x86656080
[ 1070.151809] nova: nova_save_blocknode_mappings_to_log: 50 blocknodes, 1 log pages, pi head 0x86658000, tail 0x86658320
[ 1070.222316] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1070.222319] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1070.222456] nova: Start NOVA snapshot cleaner thread.
[ 1070.222465] nova: Running snapshot cleaner thread
[ 1070.222474] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1070.222477] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1070.222478] nova: NOVA: Normal shutdown
[ 1070.225938] nova: Current epoch id: 0
[ 1070.538885] nova: Current epoch id: 0
[ 1070.538935] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x176656000, tail 0x176656080
[ 1070.538950] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x176657000, tail 0x176657380
[ 1070.547711] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1070.547713] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1070.547783] nova: Start NOVA snapshot cleaner thread.
[ 1070.547789] nova: Running snapshot cleaner thread
[ 1070.547803] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1070.547805] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1070.547806] nova: NOVA: Normal shutdown
[ 1070.551066] nova: Current epoch id: 0
[ 1070.572797] run fstests generic/340 at 2017-06-13 21:27:09
[ 1070.774863] nova: Current epoch id: 0
[ 1070.774917] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x176656000, tail 0x176656080
[ 1070.774932] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x176657000, tail 0x176657380
[ 1070.784350] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1070.784352] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1070.784477] nova: Start NOVA snapshot cleaner thread.
[ 1070.784486] nova: Running snapshot cleaner thread
[ 1070.784492] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1070.784494] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1070.784495] nova: NOVA: Normal shutdown
[ 1070.787629] nova: Current epoch id: 0
[ 1070.818912] nova: Current epoch id: 0
[ 1070.818955] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1ee657000, tail 0x1ee657080
[ 1070.818971] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x1ee658000, tail 0x1ee658390
[ 1070.824718] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1070.824720] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1070.824846] nova: Start NOVA snapshot cleaner thread.
[ 1070.824849] nova: Running snapshot cleaner thread
[ 1070.824866] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1070.824869] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1070.824869] nova: NOVA: Normal shutdown
[ 1070.828069] nova: Current epoch id: 0
[ 1072.966874] nova: Current epoch id: 0
[ 1072.966974] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0xfe656000, tail 0xfe656080
[ 1072.966990] nova: nova_save_blocknode_mappings_to_log: 56 blocknodes, 1 log pages, pi head 0xfe658000, tail 0xfe658380
[ 1072.978028] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1072.978030] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1072.978187] nova: Start NOVA snapshot cleaner thread.
[ 1072.978196] nova: Running snapshot cleaner thread
[ 1072.978219] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1072.978223] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1072.978223] nova: NOVA: Normal shutdown
[ 1072.982117] nova: Current epoch id: 0
[ 1073.004191] run fstests generic/341 at 2017-06-13 21:27:11
[ 1073.193290] run fstests generic/342 at 2017-06-13 21:27:12
[ 1073.366135] run fstests generic/343 at 2017-06-13 21:27:12
[ 1073.548467] run fstests generic/344 at 2017-06-13 21:27:12
[ 1073.734861] nova: Current epoch id: 0
[ 1073.734911] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0xe65e000, tail 0xe65e080
[ 1073.734927] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0xe65f000, tail 0xe65f390
[ 1073.769472] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1073.769475] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1073.769600] nova: Start NOVA snapshot cleaner thread.
[ 1073.769607] nova: Running snapshot cleaner thread
[ 1073.769614] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1073.769616] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1073.769617] nova: NOVA: Normal shutdown
[ 1073.772768] nova: Current epoch id: 0
[ 1073.806892] nova: Current epoch id: 0
[ 1073.806942] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x86656000, tail 0x86656080
[ 1073.806957] nova: nova_save_blocknode_mappings_to_log: 56 blocknodes, 1 log pages, pi head 0x86658000, tail 0x86658380
[ 1073.813063] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1073.813065] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1073.813164] nova: Start NOVA snapshot cleaner thread.
[ 1073.813170] nova: Running snapshot cleaner thread
[ 1073.813177] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1073.813179] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1073.813180] nova: NOVA: Normal shutdown
[ 1073.816341] nova: Current epoch id: 0
[ 1079.166886] nova: Current epoch id: 0
[ 1079.166948] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1ee657000, tail 0x1ee657080
[ 1079.166972] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x1ee658000, tail 0x1ee658390
[ 1079.178443] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1079.178447] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1079.178532] nova: Start NOVA snapshot cleaner thread.
[ 1079.178541] nova: Running snapshot cleaner thread
[ 1079.178557] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1079.178560] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1079.178560] nova: NOVA: Normal shutdown
[ 1079.182573] nova: Current epoch id: 0
[ 1079.205618] run fstests generic/345 at 2017-06-13 21:27:18
[ 1079.394860] nova: Current epoch id: 0
[ 1079.394918] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0xe65e000, tail 0xe65e080
[ 1079.394934] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0xe65f000, tail 0xe65f390
[ 1079.497841] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1079.497843] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1079.497946] nova: Start NOVA snapshot cleaner thread.
[ 1079.497953] nova: Running snapshot cleaner thread
[ 1079.497970] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1079.497972] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1079.497973] nova: NOVA: Normal shutdown
[ 1079.501139] nova: Current epoch id: 0
[ 1079.546880] nova: Current epoch id: 0
[ 1079.546924] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x356656000, tail 0x356656080
[ 1079.546939] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x356657000, tail 0x356657390
[ 1079.552858] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1079.552860] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1079.552967] nova: Start NOVA snapshot cleaner thread.
[ 1079.552976] nova: Running snapshot cleaner thread
[ 1079.552982] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1079.552984] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1079.552984] nova: NOVA: Normal shutdown
[ 1079.556118] nova: Current epoch id: 0
[ 1085.162846] nova: Current epoch id: 0
[ 1085.162895] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1ee657000, tail 0x1ee657080
[ 1085.162912] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x1ee658000, tail 0x1ee658390
[ 1085.171620] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1085.171622] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1085.171716] nova: Start NOVA snapshot cleaner thread.
[ 1085.171726] nova: Running snapshot cleaner thread
[ 1085.171729] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1085.171732] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1085.171732] nova: NOVA: Normal shutdown
[ 1085.174782] nova: Current epoch id: 0
[ 1085.194676] run fstests generic/346 at 2017-06-13 21:27:24
[ 1085.366871] nova: Current epoch id: 0
[ 1085.366927] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1ee657000, tail 0x1ee657080
[ 1085.366943] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x1ee658000, tail 0x1ee658390
[ 1085.374375] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1085.374377] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1085.374452] nova: Start NOVA snapshot cleaner thread.
[ 1085.374459] nova: Running snapshot cleaner thread
[ 1085.374466] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1085.374468] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1085.374469] nova: NOVA: Normal shutdown
[ 1085.377579] nova: Current epoch id: 0
[ 1085.410901] nova: Current epoch id: 0
[ 1085.410952] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x176656000, tail 0x176656080
[ 1085.410981] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x176657000, tail 0x176657380
[ 1085.416437] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1085.416439] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1085.416522] nova: Start NOVA snapshot cleaner thread.
[ 1085.416530] nova: Running snapshot cleaner thread
[ 1085.416536] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1085.416539] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1085.416539] nova: NOVA: Normal shutdown
[ 1085.419722] nova: Current epoch id: 0
[ 1087.614854] nova: Current epoch id: 0
[ 1087.614890] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1ee657000, tail 0x1ee657080
[ 1087.614905] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x1ee658000, tail 0x1ee658390
[ 1087.623534] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1087.623536] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1087.623607] nova: Start NOVA snapshot cleaner thread.
[ 1087.623614] nova: Running snapshot cleaner thread
[ 1087.623620] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1087.623622] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1087.623623] nova: NOVA: Normal shutdown
[ 1087.626739] nova: Current epoch id: 0
[ 1087.697705] run fstests generic/347 at 2017-06-13 21:27:26
[ 1087.902833] nova: Current epoch id: 0
[ 1087.902885] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0xfe656000, tail 0xfe656080
[ 1087.902901] nova: nova_save_blocknode_mappings_to_log: 56 blocknodes, 1 log pages, pi head 0xfe658000, tail 0xfe658380
[ 1087.925655] run fstests generic/348 at 2017-06-13 21:27:26
[ 1088.082516] run fstests generic/349 at 2017-06-13 21:27:26
[ 1088.236982] run fstests generic/350 at 2017-06-13 21:27:27
[ 1088.390177] run fstests generic/351 at 2017-06-13 21:27:27
[ 1088.545075] run fstests generic/352 at 2017-06-13 21:27:27
[ 1088.708163] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1088.708165] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1088.708263] nova: Start NOVA snapshot cleaner thread.
[ 1088.708271] nova: Running snapshot cleaner thread
[ 1088.708277] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1088.708280] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1088.708280] nova: NOVA: Normal shutdown
[ 1088.711496] nova: Current epoch id: 0
[ 1088.738906] nova: Current epoch id: 0
[ 1088.738959] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x86656000, tail 0x86656080
[ 1088.738974] nova: nova_save_blocknode_mappings_to_log: 56 blocknodes, 1 log pages, pi head 0x86658000, tail 0x86658380
[ 1088.744574] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1088.744576] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1088.744651] nova: Start NOVA snapshot cleaner thread.
[ 1088.744659] nova: Running snapshot cleaner thread
[ 1088.744664] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1088.744667] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1088.744667] nova: NOVA: Normal shutdown
[ 1088.747792] nova: Current epoch id: 0
[ 1088.770909] nova: Current epoch id: 0
[ 1088.770953] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1ee657000, tail 0x1ee657080
[ 1088.770967] nova: nova_save_blocknode_mappings_to_log: 53 blocknodes, 1 log pages, pi head 0x1ee658000, tail 0x1ee658350
[ 1088.790859] run fstests generic/353 at 2017-06-13 21:27:27
[ 1088.957662] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1088.957664] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1088.957774] nova: Start NOVA snapshot cleaner thread.
[ 1088.957782] nova: Running snapshot cleaner thread
[ 1088.957787] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1088.957789] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1088.957789] nova: NOVA: Normal shutdown
[ 1088.960987] nova: Current epoch id: 0
[ 1088.998904] nova: Current epoch id: 0
[ 1088.998959] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x176656000, tail 0x176656080
[ 1088.998979] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x176657000, tail 0x176657380
[ 1089.004556] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1089.004558] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1089.004644] nova: Start NOVA snapshot cleaner thread.
[ 1089.004658] nova: Running snapshot cleaner thread
[ 1089.004663] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1089.004666] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1089.004666] nova: NOVA: Normal shutdown
[ 1089.007765] nova: Current epoch id: 0
[ 1089.034844] nova: Current epoch id: 0
[ 1089.034882] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1ee657000, tail 0x1ee657080
[ 1089.034897] nova: nova_save_blocknode_mappings_to_log: 55 blocknodes, 1 log pages, pi head 0x1ee658000, tail 0x1ee658370
[ 1089.055372] run fstests generic/354 at 2017-06-13 21:27:27
[ 1089.207157] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1089.207159] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1089.207268] nova: Start NOVA snapshot cleaner thread.
[ 1089.207275] nova: Running snapshot cleaner thread
[ 1089.207282] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1089.207284] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1089.207284] nova: NOVA: Normal shutdown
[ 1089.210490] nova: Current epoch id: 0
[ 1089.234889] nova: Current epoch id: 0
[ 1089.234992] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x266657000, tail 0x266657080
[ 1089.235007] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x266658000, tail 0x266658390
[ 1089.240227] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1089.240229] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1089.240326] nova: Start NOVA snapshot cleaner thread.
[ 1089.240332] nova: Running snapshot cleaner thread
[ 1089.240340] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1089.240342] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1089.240342] nova: NOVA: Normal shutdown
[ 1089.243491] nova: Current epoch id: 0
[ 1092.574846] nova: Current epoch id: 0
[ 1092.574902] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x86656000, tail 0x86656080
[ 1092.574918] nova: nova_save_blocknode_mappings_to_log: 56 blocknodes, 1 log pages, pi head 0x86658000, tail 0x86658380
[ 1092.583834] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1092.583836] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1092.583933] nova: Start NOVA snapshot cleaner thread.
[ 1092.583941] nova: Running snapshot cleaner thread
[ 1092.583947] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1092.583950] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1092.583950] nova: NOVA: Normal shutdown
[ 1092.587081] nova: Current epoch id: 0
[ 1092.607768] run fstests generic/355 at 2017-06-13 21:27:31
[ 1092.887050] nova: Current epoch id: 0
[ 1092.887110] nova: nova_save_inode_list_to_log: 17 inode nodes, pi head 0x1379c000, tail 0x1379c110
[ 1092.887182] nova: nova_save_blocknode_mappings_to_log: 269 blocknodes, 2 log pages, pi head 0x1379e000, tail 0x1379f0f0
[ 1092.897892] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 1092.897895] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1092.898029] nova: Start NOVA snapshot cleaner thread.
[ 1092.898037] nova: Running snapshot cleaner thread
[ 1092.898094] nova: nova_init_inode_list_from_inode: 17 inode nodes
[ 1092.898097] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1092.898098] nova: NOVA: Normal shutdown
[ 1092.901557] nova: Current epoch id: 0
[ 1092.924629] run fstests generic/356 at 2017-06-13 21:27:31
[ 1093.122838] nova: Current epoch id: 0
[ 1093.122909] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x176656000, tail 0x176656080
[ 1093.122925] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x176657000, tail 0x176657380
[ 1093.135354] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1093.135356] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1093.135554] nova: Start NOVA snapshot cleaner thread.
[ 1093.135560] nova: Running snapshot cleaner thread
[ 1093.135575] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1093.135577] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1093.135577] nova: NOVA: Normal shutdown
[ 1093.138839] nova: Current epoch id: 0
[ 1093.158985] nova: Current epoch id: 0
[ 1093.159036] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x266657000, tail 0x266657080
[ 1093.159052] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x266658000, tail 0x266658390
[ 1093.164656] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1093.164658] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1093.164773] nova: Start NOVA snapshot cleaner thread.
[ 1093.164782] nova: Running snapshot cleaner thread
[ 1093.164787] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1093.164789] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1093.164789] nova: NOVA: Normal shutdown
[ 1093.167915] nova: Current epoch id: 0
[ 1093.198861] nova: Current epoch id: 0
[ 1093.198900] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x266657000, tail 0x266657080
[ 1093.198918] nova: nova_save_blocknode_mappings_to_log: 52 blocknodes, 1 log pages, pi head 0x266658000, tail 0x266658340
[ 1093.223050] run fstests generic/357 at 2017-06-13 21:27:32
[ 1093.401695] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1093.401697] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1093.401788] nova: Start NOVA snapshot cleaner thread.
[ 1093.401804] nova: Running snapshot cleaner thread
[ 1093.401805] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1093.401807] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1093.401807] nova: NOVA: Normal shutdown
[ 1093.404932] nova: Current epoch id: 0
[ 1093.430893] nova: Current epoch id: 0
[ 1093.430954] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x176656000, tail 0x176656080
[ 1093.430970] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x176657000, tail 0x176657380
[ 1093.436267] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1093.436269] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1093.436345] nova: Start NOVA snapshot cleaner thread.
[ 1093.436354] nova: Running snapshot cleaner thread
[ 1093.436359] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1093.436361] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1093.436362] nova: NOVA: Normal shutdown
[ 1093.439512] nova: Current epoch id: 0
[ 1093.458845] nova: Current epoch id: 0
[ 1093.458888] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x86656000, tail 0x86656080
[ 1093.458902] nova: nova_save_blocknode_mappings_to_log: 50 blocknodes, 1 log pages, pi head 0x86658000, tail 0x86658320
[ 1093.480025] run fstests generic/358 at 2017-06-13 21:27:32
[ 1093.643898] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1093.643900] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1093.643988] nova: Start NOVA snapshot cleaner thread.
[ 1093.643997] nova: Running snapshot cleaner thread
[ 1093.644002] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1093.644004] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1093.644004] nova: NOVA: Normal shutdown
[ 1093.647140] nova: Current epoch id: 0
[ 1093.674890] nova: Current epoch id: 0
[ 1093.674944] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x2de65f000, tail 0x2de65f080
[ 1093.674960] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x2de660000, tail 0x2de660390
[ 1093.680164] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1093.680166] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1093.680243] nova: Start NOVA snapshot cleaner thread.
[ 1093.680249] nova: Running snapshot cleaner thread
[ 1093.680262] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1093.680264] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1093.680264] nova: NOVA: Normal shutdown
[ 1093.683428] nova: Current epoch id: 0
[ 1093.702870] nova: Current epoch id: 0
[ 1093.702917] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x266657000, tail 0x266657080
[ 1093.702931] nova: nova_save_blocknode_mappings_to_log: 52 blocknodes, 1 log pages, pi head 0x266658000, tail 0x266658340
[ 1093.722662] run fstests generic/359 at 2017-06-13 21:27:32
[ 1093.886219] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1093.886221] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1093.886334] nova: Start NOVA snapshot cleaner thread.
[ 1093.886343] nova: Running snapshot cleaner thread
[ 1093.886348] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1093.886350] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1093.886350] nova: NOVA: Normal shutdown
[ 1093.889553] nova: Current epoch id: 0
[ 1093.914913] nova: Current epoch id: 0
[ 1093.914961] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x176656000, tail 0x176656080
[ 1093.914975] nova: nova_save_blocknode_mappings_to_log: 57 blocknodes, 1 log pages, pi head 0x176657000, tail 0x176657380
[ 1093.920158] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x780000000, virt_addr ffff960100000000, size 16106127360
[ 1093.920160] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1093.920227] nova: Start NOVA snapshot cleaner thread.
[ 1093.920235] nova: Running snapshot cleaner thread
[ 1093.920239] nova: nova_init_inode_list_from_inode: 8 inode nodes
[ 1093.920242] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1093.920242] nova: NOVA: Normal shutdown
[ 1093.923354] nova: Current epoch id: 0
[ 1093.950847] nova: Current epoch id: 0
[ 1093.950894] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x266657000, tail 0x266657080
[ 1093.950910] nova: nova_save_blocknode_mappings_to_log: 56 blocknodes, 1 log pages, pi head 0x266658000, tail 0x266658380
[ 1093.970844] run fstests generic/360 at 2017-06-13 21:27:32
[ 1094.186987] nova: Current epoch id: 0
[ 1094.187038] nova: nova_save_inode_list_to_log: 17 inode nodes, pi head 0x1379c000, tail 0x1379c110
[ 1094.187097] nova: nova_save_blocknode_mappings_to_log: 269 blocknodes, 2 log pages, pi head 0x1379e000, tail 0x1379f0f0
[ 1094.195687] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 1094.195689] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 1094.195793] nova: Start NOVA snapshot cleaner thread.
[ 1094.195799] nova: Running snapshot cleaner thread
[ 1094.195845] nova: nova_init_inode_list_from_inode: 17 inode nodes
[ 1094.195847] nova: Recovered 0 snapshots, latest epoch ID 0
[ 1094.195848] nova: NOVA: Normal shutdown
[ 1094.198051] nova: Current epoch id: 0
[ 1094.217723] run fstests generic/361 at 2017-06-13 21:27:33
[ 1094.390332] run fstests generic/362 at 2017-06-13 21:27:33
[ 1094.555244] run fstests generic/363 at 2017-06-13 21:27:33
[ 1094.732231] run fstests generic/364 at 2017-06-13 21:27:33
[ 1094.918696] run fstests generic/365 at 2017-06-13 21:27:33
[ 1095.112954] run fstests generic/366 at 2017-06-13 21:27:33
[ 1095.313351] run fstests generic/367 at 2017-06-13 21:27:34
[ 1095.525719] run fstests generic/368 at 2017-06-13 21:27:34
[ 1095.765772] run fstests generic/369 at 2017-06-13 21:27:34
[ 1095.979956] run fstests generic/370 at 2017-06-13 21:27:34
[ 1096.203190] run fstests shared/001 at 2017-06-13 21:27:35
[ 1096.411449] run fstests shared/002 at 2017-06-13 21:27:35
[ 1096.599096] run fstests shared/003 at 2017-06-13 21:27:35
[ 1096.785760] run fstests shared/004 at 2017-06-13 21:27:35
[ 1096.968559] run fstests shared/006 at 2017-06-13 21:27:35
[ 1097.149328] run fstests shared/032 at 2017-06-13 21:27:35
[ 1097.349243] run fstests shared/051 at 2017-06-13 21:27:36
[ 1097.535033] run fstests shared/272 at 2017-06-13 21:27:36
[ 1097.705330] run fstests shared/289 at 2017-06-13 21:27:36
[ 1097.885625] run fstests shared/298 at 2017-06-13 21:27:36
[ 1098.114981] nova: Current epoch id: 0
[ 1098.115039] nova: nova_save_inode_list_to_log: 17 inode nodes, pi head 0x333837000, tail 0x333837110
[ 1098.115097] nova: nova_save_blocknode_mappings_to_log: 270 blocknodes, 2 log pages, pi head 0x333838000, tail 0x333839100
[ 2233.291562] EXT4-fs (loop1): mounting ext3 file system using the ext4 subsystem
[ 2233.294797] EXT4-fs (loop1): mounted filesystem with ordered data mode. Opts: usrquota,grpquota
[ 2233.329583] EXT4-fs (loop1): re-mounted. Opts: (null)
[ 2233.333116] EXT4-fs (loop1): re-mounted. Opts: (null)
[ 2240.923460] drop-caches (25336): drop_caches: 3
[ 2242.464826] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2242.464829] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2242.464981] nova: Start NOVA snapshot cleaner thread.
[ 2242.464983] nova: creating an empty nova of size 21474836480
[ 2242.464989] nova: Running snapshot cleaner thread
[ 2242.467095] nova: NOVA initialization finish
[ 2242.467106] nova: Current epoch id: 0
[ 2242.509084] drop-caches (25456): drop_caches: 3
[ 2251.797477] nova: nova_cow_file_write alloc blocks failed -28
[ 2251.797479] nova: nova_cow_file_write alloc blocks failed -28
[ 2251.797481] nova: nova_cow_file_write alloc blocks failed -28
[ 2251.797482] nova: nova_cow_file_write alloc blocks failed -28
[ 2252.206307] drop-caches (25489): drop_caches: 3
[ 2253.331276] nova: Current epoch id: 0
[ 2253.331314] nova error:
[ 2253.331315] ERROR: no inode log page available: 1 -28
[ 2253.331316] nova: Error saving inode list: -28
[ 2253.331316] nova error:
[ 2253.331317] ERROR: no inode log page available: 0 -22
[ 2253.331317] nova: Error saving blocknode mappings: -22
[ 2253.411165] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2253.411167] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2253.411278] nova: Start NOVA snapshot cleaner thread.
[ 2253.411281] nova: creating an empty nova of size 21474836480
[ 2253.411286] nova: Running snapshot cleaner thread
[ 2253.413416] nova: NOVA initialization finish
[ 2253.413429] nova: Current epoch id: 0
[ 2253.465026] drop-caches (25511): drop_caches: 3
[ 2262.734509] nova: nova_cow_file_write alloc blocks failed -28
[ 2262.734513] nova: nova_cow_file_write alloc blocks failed -28
[ 2263.136655] drop-caches (25540): drop_caches: 3
[ 2264.539293] nova: Current epoch id: 0
[ 2264.539374] nova error:
[ 2264.539375] ERROR: no inode log page available: 1 -28
[ 2264.539376] nova: Error saving inode list: -28
[ 2264.539376] nova error:
[ 2264.539377] ERROR: no inode log page available: 0 -22
[ 2264.539377] nova: Error saving blocknode mappings: -22
[ 2264.600054] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2264.600057] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2264.600179] nova: Start NOVA snapshot cleaner thread.
[ 2264.600181] nova: creating an empty nova of size 21474836480
[ 2264.600187] nova: Running snapshot cleaner thread
[ 2264.602296] nova: NOVA initialization finish
[ 2264.602304] nova: Current epoch id: 0
[ 2264.679735] drop-caches (25562): drop_caches: 3
[ 2281.201397] drop-caches (25587): drop_caches: 3
[ 2282.451272] nova: Current epoch id: 0
[ 2282.451353] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1cdd56000, tail 0x1cdd56080
[ 2282.451360] nova: nova_save_blocknode_mappings_to_log: 7 blocknodes, 1 log pages, pi head 0x26dd56000, tail 0x26dd56070
[ 2282.505200] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2282.505203] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2282.505315] nova: Start NOVA snapshot cleaner thread.
[ 2282.505317] nova: creating an empty nova of size 21474836480
[ 2282.505323] nova: Running snapshot cleaner thread
[ 2282.507450] nova: NOVA initialization finish
[ 2282.507459] nova: Current epoch id: 0
[ 2282.551944] drop-caches (25609): drop_caches: 3
[ 2298.598691] drop-caches (25642): drop_caches: 3
[ 2299.791289] nova: Current epoch id: 0
[ 2299.791343] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1327c000, tail 0x1327c080
[ 2299.791358] nova: nova_save_blocknode_mappings_to_log: 48 blocknodes, 1 log pages, pi head 0x1327f000, tail 0x1327f300
[ 2299.877244] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2299.877247] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2299.877327] nova: Start NOVA snapshot cleaner thread.
[ 2299.877329] nova: creating an empty nova of size 21474836480
[ 2299.877334] nova: Running snapshot cleaner thread
[ 2299.879495] nova: NOVA initialization finish
[ 2299.879503] nova: Current epoch id: 0
[ 2299.942202] drop-caches (25664): drop_caches: 3
[ 2316.245515] drop-caches (25691): drop_caches: 3
[ 2317.627292] nova: Current epoch id: 0
[ 2317.627366] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1327c000, tail 0x1327c080
[ 2317.627377] nova: nova_save_blocknode_mappings_to_log: 28 blocknodes, 1 log pages, pi head 0x1327d000, tail 0x1327d1c0
[ 2317.698630] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2317.698632] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2317.698780] nova: Start NOVA snapshot cleaner thread.
[ 2317.698782] nova: creating an empty nova of size 21474836480
[ 2317.698790] nova: Running snapshot cleaner thread
[ 2317.701162] nova: NOVA initialization finish
[ 2317.701173] nova: Current epoch id: 0
[ 2317.747317] drop-caches (25713): drop_caches: 3
[ 2333.756977] drop-caches (25737): drop_caches: 3
[ 2335.039283] nova: Current epoch id: 0
[ 2335.039346] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x13284000, tail 0x13284080
[ 2335.039354] nova: nova_save_blocknode_mappings_to_log: 17 blocknodes, 1 log pages, pi head 0x13288000, tail 0x13288110
[ 2335.095789] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2335.095791] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2335.095910] nova: Start NOVA snapshot cleaner thread.
[ 2335.095913] nova: creating an empty nova of size 21474836480
[ 2335.095918] nova: Running snapshot cleaner thread
[ 2335.098018] nova: NOVA initialization finish
[ 2335.098026] nova: Current epoch id: 0
[ 2335.161150] drop-caches (25759): drop_caches: 3
[ 2351.378847] drop-caches (25786): drop_caches: 3
[ 2352.651816] nova: Current epoch id: 0
[ 2352.651893] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x13283000, tail 0x13283080
[ 2352.651901] nova: nova_save_blocknode_mappings_to_log: 16 blocknodes, 1 log pages, pi head 0x142d4000, tail 0x142d40f0
[ 2352.717980] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2352.717984] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2352.718111] nova: Start NOVA snapshot cleaner thread.
[ 2352.718114] nova: creating an empty nova of size 21474836480
[ 2352.718122] nova: Running snapshot cleaner thread
[ 2352.720716] nova: NOVA initialization finish
[ 2352.720733] nova: Current epoch id: 0
[ 2352.768312] drop-caches (25808): drop_caches: 3
[ 2368.852799] drop-caches (25833): drop_caches: 3
[ 2370.035534] nova: Current epoch id: 0
[ 2370.035594] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1327a000, tail 0x1327a080
[ 2370.035601] nova: nova_save_blocknode_mappings_to_log: 13 blocknodes, 1 log pages, pi head 0x13963000, tail 0x139630d0
[ 2370.106559] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2370.106561] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2370.106714] nova: Start NOVA snapshot cleaner thread.
[ 2370.106717] nova: creating an empty nova of size 21474836480
[ 2370.106720] nova: Running snapshot cleaner thread
[ 2370.109079] nova: NOVA initialization finish
[ 2370.109089] nova: Current epoch id: 0
[ 2370.158135] drop-caches (25855): drop_caches: 3
[ 2386.414767] drop-caches (25879): drop_caches: 3
[ 2387.739418] nova: Current epoch id: 0
[ 2387.739511] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1394a000, tail 0x1394a080
[ 2387.739518] nova: nova_save_blocknode_mappings_to_log: 14 blocknodes, 1 log pages, pi head 0x1394b000, tail 0x1394b0e0
[ 2387.803004] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2387.803006] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2387.803197] nova: Start NOVA snapshot cleaner thread.
[ 2387.803199] nova: creating an empty nova of size 21474836480
[ 2387.803211] nova: Running snapshot cleaner thread
[ 2387.805574] nova: NOVA initialization finish
[ 2387.805585] nova: Current epoch id: 0
[ 2387.846192] drop-caches (25901): drop_caches: 3
[ 2403.932562] drop-caches (25934): drop_caches: 3
[ 2404.971327] nova: Current epoch id: 0
[ 2404.971383] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x13284000, tail 0x13284080
[ 2404.971399] nova: nova_save_blocknode_mappings_to_log: 51 blocknodes, 1 log pages, pi head 0x13286000, tail 0x13286330
[ 2405.024727] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2405.024729] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2405.024807] nova: Start NOVA snapshot cleaner thread.
[ 2405.024810] nova: creating an empty nova of size 21474836480
[ 2405.024815] nova: Running snapshot cleaner thread
[ 2405.026934] nova: NOVA initialization finish
[ 2405.026943] nova: Current epoch id: 0
[ 2405.075656] drop-caches (25956): drop_caches: 3
[ 2421.259372] drop-caches (25983): drop_caches: 3
[ 2422.399302] nova: Current epoch id: 0
[ 2422.399351] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1327c000, tail 0x1327c080
[ 2422.399362] nova: nova_save_blocknode_mappings_to_log: 29 blocknodes, 1 log pages, pi head 0x1327d000, tail 0x1327d1d0
[ 2422.471888] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2422.471890] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2422.472104] nova: Start NOVA snapshot cleaner thread.
[ 2422.472106] nova: creating an empty nova of size 21474836480
[ 2422.472114] nova: Running snapshot cleaner thread
[ 2422.474232] nova: NOVA initialization finish
[ 2422.474242] nova: Current epoch id: 0
[ 2422.537519] drop-caches (26005): drop_caches: 3
[ 2438.662492] drop-caches (26029): drop_caches: 3
[ 2439.847322] nova: Current epoch id: 0
[ 2439.847385] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x13284000, tail 0x13284080
[ 2439.847393] nova: nova_save_blocknode_mappings_to_log: 18 blocknodes, 1 log pages, pi head 0x13286000, tail 0x13286120
[ 2439.926939] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2439.926941] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2439.927064] nova: Start NOVA snapshot cleaner thread.
[ 2439.927066] nova: creating an empty nova of size 21474836480
[ 2439.927075] nova: Running snapshot cleaner thread
[ 2439.929428] nova: NOVA initialization finish
[ 2439.929439] nova: Current epoch id: 0
[ 2439.982758] drop-caches (26051): drop_caches: 3
[ 2456.360535] drop-caches (26084): drop_caches: 3
[ 2457.707338] nova: Current epoch id: 0
[ 2457.707413] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x13285000, tail 0x13285080
[ 2457.707426] nova: nova_save_blocknode_mappings_to_log: 43 blocknodes, 1 log pages, pi head 0x1328c000, tail 0x1328c2b0
[ 2457.815631] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2457.815632] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2457.815723] nova: Start NOVA snapshot cleaner thread.
[ 2457.815725] nova: creating an empty nova of size 21474836480
[ 2457.815727] nova: Running snapshot cleaner thread
[ 2457.817848] nova: NOVA initialization finish
[ 2457.817856] nova: Current epoch id: 0
[ 2457.862048] drop-caches (26106): drop_caches: 3
[ 2474.025741] drop-caches (26133): drop_caches: 3
[ 2475.219331] nova: Current epoch id: 0
[ 2475.219382] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x13286000, tail 0x13286080
[ 2475.219391] nova: nova_save_blocknode_mappings_to_log: 25 blocknodes, 1 log pages, pi head 0x13287000, tail 0x13287190
[ 2475.279049] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2475.279052] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2475.279143] nova: Start NOVA snapshot cleaner thread.
[ 2475.279146] nova: creating an empty nova of size 21474836480
[ 2475.279153] nova: Running snapshot cleaner thread
[ 2475.281287] nova: NOVA initialization finish
[ 2475.281296] nova: Current epoch id: 0
[ 2475.336790] drop-caches (26155): drop_caches: 3
[ 2491.716136] drop-caches (26179): drop_caches: 3
[ 2493.143340] nova: Current epoch id: 0
[ 2493.143392] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1327c000, tail 0x1327c080
[ 2493.143399] nova: nova_save_blocknode_mappings_to_log: 16 blocknodes, 1 log pages, pi head 0x13283000, tail 0x13283100
[ 2493.200688] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2493.200690] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2493.200849] nova: Start NOVA snapshot cleaner thread.
[ 2493.200851] nova: creating an empty nova of size 21474836480
[ 2493.200860] nova: Running snapshot cleaner thread
[ 2493.202965] nova: NOVA initialization finish
[ 2493.202974] nova: Current epoch id: 0
[ 2493.266869] drop-caches (26201): drop_caches: 3
[ 2537.582502] drop-caches (26250): drop_caches: 3
[ 2540.965803] nova: Current epoch id: 0
[ 2540.966260] nova: nova_save_inode_list_to_log: 1921 inode nodes, pi head 0x297073000, tail 0x29707a8f0
[ 2540.966266] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x29707b000, tail 0x29707b080
[ 2542.061231] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2542.061232] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2542.061319] nova: Start NOVA snapshot cleaner thread.
[ 2542.061321] nova: creating an empty nova of size 21474836480
[ 2542.061327] nova: Running snapshot cleaner thread
[ 2542.063506] nova: NOVA initialization finish
[ 2542.063515] nova: Current epoch id: 0
[ 2542.114263] drop-caches (26272): drop_caches: 3
[ 2583.718982] drop-caches (26300): drop_caches: 3
[ 2587.712608] nova: Current epoch id: 0
[ 2587.712729] nova: nova_save_inode_list_to_log: 259 inode nodes, pi head 0x296473000, tail 0x296474050
[ 2587.712735] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x296475000, tail 0x296475080
[ 2588.784277] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2588.784280] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2588.784401] nova: Start NOVA snapshot cleaner thread.
[ 2588.784404] nova: creating an empty nova of size 21474836480
[ 2588.784408] nova: Running snapshot cleaner thread
[ 2588.786572] nova: NOVA initialization finish
[ 2588.786585] nova: Current epoch id: 0
[ 2588.840582] drop-caches (26322): drop_caches: 3
[ 2625.442381] drop-caches (26346): drop_caches: 3
[ 2628.275028] nova: Current epoch id: 0
[ 2628.275100] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x2b3327000, tail 0x2b3327080
[ 2628.275105] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x2b3328000, tail 0x2b3328080
[ 2629.334814] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2629.334816] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2629.334929] nova: Start NOVA snapshot cleaner thread.
[ 2629.334931] nova: creating an empty nova of size 21474836480
[ 2629.334938] nova: Running snapshot cleaner thread
[ 2629.337166] nova: NOVA initialization finish
[ 2629.337175] nova: Current epoch id: 0
[ 2629.375510] drop-caches (26368): drop_caches: 3
[ 2642.112246] fxmark invoked oom-killer: gfp_mask=0x16040c0(GFP_KERNEL|__GFP_COMP|__GFP_NOTRACK), nodemask=0, order=0, oom_score_adj=0
[ 2642.112247] fxmark cpuset=/ mems_allowed=0
[ 2642.112251] CPU: 3 PID: 26373 Comm: fxmark Tainted: G OE 4.10.0-rc8-nova #4
[ 2642.112252] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
[ 2642.112253] Call Trace:
[ 2642.112259] dump_stack+0x63/0x81
[ 2642.112262] dump_header+0x7b/0x1fd
[ 2642.112266] ? apparmor_capable+0x2f/0x40
[ 2642.112268] oom_kill_process+0x208/0x3e0
[ 2642.112269] out_of_memory+0x120/0x4c0
[ 2642.112272] __alloc_pages_slowpath+0xb37/0xba0
[ 2642.112274] __alloc_pages_nodemask+0x209/0x260
[ 2642.112276] alloc_pages_current+0x95/0x140
[ 2642.112279] new_slab+0x425/0x6f0
[ 2642.112280] ___slab_alloc+0x3a0/0x4b0
[ 2642.112283] ? get_empty_filp+0x5c/0x1c0
[ 2642.112284] ? get_empty_filp+0x5c/0x1c0
[ 2642.112286] __slab_alloc+0x20/0x40
[ 2642.112287] kmem_cache_alloc+0x15e/0x1a0
[ 2642.112289] get_empty_filp+0x5c/0x1c0
[ 2642.112290] path_openat+0x40/0x14f0
[ 2642.112292] do_filp_open+0x91/0x100
[ 2642.112293] ? list_lru_add+0x5a/0x120
[ 2642.112295] ? __alloc_fd+0x46/0x170
[ 2642.112296] do_sys_open+0x130/0x220
[ 2642.112297] SyS_open+0x1e/0x20
[ 2642.112299] entry_SYSCALL_64_fastpath+0x1e/0xad
[ 2642.112300] RIP: 0033:0x7f8907ab7a70
[ 2642.112301] RSP: 002b:00007ffc1d18b0e8 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
[ 2642.112302] RAX: ffffffffffffffda RBX: 0000000000116ca5 RCX: 00007f8907ab7a70
[ 2642.112302] RDX: 00000000000001c0 RSI: 0000000000000042 RDI: 00007ffc1d18c100
[ 2642.112303] RBP: 00007ffc1d18c100 R08: 0000000000000001 R09: 0000000000000028
[ 2642.112303] R10: 0000000000000075 R11: 0000000000000246 R12: 00007f8907f9f000
[ 2642.112304] R13: 00007ffc1d18b100 R14: 00007f8907fa81c0 R15: 000056316fe65532
[ 2642.112305] Mem-Info:
[ 2642.112309] active_anon:467465 inactive_anon:2221 isolated_anon:0
active_file:4546 inactive_file:4386 isolated_file:0
unevictable:912 dirty:2 writeback:0 unstable:0
slab_reclaimable:3659301 slab_unreclaimable:16059
mapped:9567 shmem:2227 pagetables:2059 bounce:0
free:34891 free_pcp:0 free_cma:0
[ 2642.112312] Node 0 active_anon:1869860kB inactive_anon:8884kB active_file:18184kB inactive_file:17544kB unevictable:3648kB isolated(anon):0kB isolated(file):0kB mapped:38268kB dirty:8kB writeback:0kB shmem:0kB shmem_thp: 0kB shmem_pmdmapped: 1705984kB anon_thp: 8908kB writeback_tmp:0kB unstable:0kB pages_scanned:0 all_unreclaimable? no
[ 2642.112312] Node 0 DMA free:15908kB min:60kB low:72kB high:84kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15908kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[ 2642.112315] lowmem_reserve[]: 0 2984 17026 17026 17026
[ 2642.112317] Node 0 DMA32 free:67996kB min:11836kB low:14892kB high:17948kB active_anon:2048kB inactive_anon:0kB active_file:4kB inactive_file:4kB unevictable:0kB writepending:0kB present:3129332kB managed:3063764kB mlocked:0kB slab_reclaimable:2993092kB slab_unreclaimable:164kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[ 2642.112319] lowmem_reserve[]: 0 0 14041 14041 14041
[ 2642.112321] Node 0 Normal free:55660kB min:55684kB low:70060kB high:84436kB active_anon:1867812kB inactive_anon:8884kB active_file:18180kB inactive_file:17540kB unevictable:3648kB writepending:8kB present:14680064kB managed:14382792kB mlocked:3648kB slab_reclaimable:11644112kB slab_unreclaimable:64072kB kernel_stack:3936kB pagetables:8236kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[ 2642.112323] lowmem_reserve[]: 0 0 0 0 0
[ 2642.112325] Node 0 DMA: 14kB (U) 08kB 016kB 132kB (U) 264kB (U) 1128kB (U) 1256kB (U) 0512kB 11024kB (U) 12048kB (M) 34096kB (M) = 15908kB
[ 2642.112331] Node 0 DMA32: 144kB (UEH) 238kB (UEH) 2616kB (UMEH) 2132kB (UE) 2364kB (UMEH) 18128kB (UMEH) 12256kB (UMH) 9512kB (UMEH) 41024kB (UMH) 32048kB (EH) 114096kB (M) = 68080kB
[ 2642.112338] Node 0 Normal: 28564kB (UMEH) 32238kB (UMEH) 30516kB (UME) 16032kB (UME) 14164kB (ME) 0128kB 0256kB 0512kB 01024kB 02048kB 0*4096kB = 56232kB
[ 2642.112345] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[ 2642.112345] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[ 2642.112346] 11728 total pagecache pages
[ 2642.112347] 0 pages in swap cache
[ 2642.112347] Swap cache stats: add 0, delete 0, find 0/0
[ 2642.112348] Free swap = 0kB
[ 2642.112348] Total swap = 0kB
[ 2642.112349] 4456347 pages RAM
[ 2642.112349] 0 pages HighMem/MovableOnly
[ 2642.112350] 90731 pages reserved
[ 2642.112350] 0 pages cma reserved
[ 2642.112350] 0 pages hwpoisoned
[ 2642.112351] [ pid ] uid tgid total_vm rss nr_ptes nr_pmds swapents oom_score_adj name
[ 2642.112355] [ 699] 0 699 11554 1748 25 3 0 0 systemd-journal
[ 2642.112357] [ 748] 0 748 25746 353 18 3 0 0 lvmetad
[ 2642.112359] [ 788] 0 788 11048 990 22 3 0 -1000 systemd-udevd
[ 2642.112360] [ 1404] 0 1404 4029 227 11 3 0 0 dhclient
[ 2642.112361] [ 1564] 0 1564 7036 552 19 3 0 0 atd
[ 2642.112362] [ 1574] 106 1574 11327 875 26 3 0 -900 dbus-daemon
[ 2642.112363] [ 1594] 102 1594 12476 967 29 3 0 0 systemd-resolve
[ 2642.112364] [ 1612] 0 1612 1097 333 8 3 0 0 acpid
[ 2642.112366] [ 1618] 0 1618 7460 686 19 3 0 0 cron
[ 2642.112367] [ 1631] 104 1631 66414 899 32 4 0 0 rsyslogd
[ 2642.112368] [ 1660] 0 1660 11638 841 26 3 0 0 systemd-logind
[ 2642.112369] [ 1667] 0 1667 70987 1377 42 4 0 0 accounts-daemon
[ 2642.112370] [ 1687] 0 1687 87738 2944 30 6 0 0 snapd
[ 2642.112371] [ 1716] 0 1716 40223 318 16 3 0 0 lxcfs
[ 2642.112373] [ 1726] 0 1726 1124 199 8 3 0 0 sshguard-journa
[ 2642.112374] [ 1728] 0 1728 11950 1335 25 3 0 0 journalctl
[ 2642.112375] [ 1729] 0 1729 4046 626 11 3 0 0 sshguard
[ 2642.112376] [ 1754] 0 1754 1124 185 8 4 0 0 sshg-fw
[ 2642.112377] [ 1829] 0 1829 71578 1306 43 3 0 0 polkitd
[ 2642.112378] [ 1963] 0 1963 1304 30 7 3 0 0 iscsid
[ 2642.112379] [ 1965] 0 1965 1429 875 8 3 0 -17 iscsid
[ 2642.112380] [ 2033] 0 2033 3623 489 12 3 0 0 agetty
[ 2642.112382] [ 2076] 0 2076 3679 425 12 3 0 0 agetty
[ 2642.112383] [ 2105] 112 2105 24490 1157 21 3 0 0 ntpd
[ 2642.112384] [ 2108] 0 2108 17103 5361 37 3 0 0 google_ip_forwa
[ 2642.112385] [ 2115] 0 2115 17086 5391 37 3 0 0 google_accounts
[ 2642.112386] [ 2122] 0 2122 17502 1270 38 3 0 -1000 sshd
[ 2642.112388] [ 2124] 0 2124 17099 5329 39 3 0 0 google_clock_sk
[ 2642.112389] [ 2143] 113 2143 16280 1031 35 3 0 0 systemd
[ 2642.112390] [ 2151] 113 2151 21784 487 44 3 0 0 (sd-pam)
[ 2642.112391] [ 2170] 113 2170 4713 45 13 3 0 0 daemon
[ 2642.112392] [ 2184] 113 2184 2556257 449971 1031 12 0 0 java
[ 2642.112394] [ 2197] 0 2197 25359 1369 54 3 0 0 sshd
[ 2642.112395] [ 2215] 1001 2215 16280 1045 35 3 0 0 systemd
[ 2642.112396] [ 2216] 1001 2216 21784 487 44 3 0 0 (sd-pam)
[ 2642.112397] [ 2367] 1001 2367 25359 754 50 3 0 0 sshd
[ 2642.112398] [ 2377] 1001 2377 5401 1012 15 3 0 0 bash
[ 2642.112400] [25320] 113 25320 1124 199 8 3 0 0 sh
[ 2642.112401] [25323] 113 25323 1124 188 7 3 0 0 script.sh
[ 2642.112402] [25324] 113 25324 12034 3341 26 3 0 0 python3
[ 2642.112403] [26369] 113 26369 1124 190 8 3 0 0 sh
[ 2642.112404] [26370] 113 26370 1075 180 7 3 0 0 fxmark
[ 2642.112405] [26371] 113 26371 1075 20 7 3 0 0 fxmark
[ 2642.112406] [26372] 113 26372 1075 20 7 3 0 0 fxmark
[ 2642.112407] [26373] 113 26373 1075 20 7 3 0 0 fxmark
[ 2642.112408] Out of memory: Kill process 2184 (java) score 103 or sacrifice child
[ 2642.129387] Killed process 25320 (sh) total-vm:4496kB, anon-rss:72kB, file-rss:724kB, shmem-rss:0kB
[ 2655.645777] drop-caches (26406): drop_caches: 3
[ 2658.723383] nova: Current epoch id: 0
[ 2658.723428] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1dc6d000, tail 0x1dc6d080
[ 2658.723434] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x1dc6e000, tail 0x1dc6e080
[ 2658.796291] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2658.796293] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2658.796377] nova: Start NOVA snapshot cleaner thread.
[ 2658.796380] nova: creating an empty nova of size 21474836480
[ 2658.796385] nova: Running snapshot cleaner thread
[ 2658.798510] nova: NOVA initialization finish
[ 2658.798520] nova: Current epoch id: 0
[ 2658.844683] drop-caches (26428): drop_caches: 3
[ 2685.079639] drop-caches (26455): drop_caches: 3
[ 2688.339457] nova: Current epoch id: 0
[ 2688.339527] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1db76000, tail 0x1db76080
[ 2688.339533] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x1db77000, tail 0x1db77080
[ 2688.416087] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2688.416090] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2688.416218] nova: Start NOVA snapshot cleaner thread.
[ 2688.416220] nova: creating an empty nova of size 21474836480
[ 2688.416239] nova: Running snapshot cleaner thread
[ 2688.418357] nova: NOVA initialization finish
[ 2688.418365] nova: Current epoch id: 0
[ 2688.457291] drop-caches (26477): drop_caches: 3
[ 2710.324384] drop-caches (26501): drop_caches: 3
[ 2711.963443] nova: Current epoch id: 0
[ 2711.963494] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1db76000, tail 0x1db76080
[ 2711.963500] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x1db77000, tail 0x1db77080
[ 2712.036692] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2712.036694] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2712.036774] nova: Start NOVA snapshot cleaner thread.
[ 2712.036776] nova: creating an empty nova of size 21474836480
[ 2712.036782] nova: Running snapshot cleaner thread
[ 2712.038913] nova: NOVA initialization finish
[ 2712.038922] nova: Current epoch id: 0
[ 2712.093655] drop-caches (26523): drop_caches: 3
[ 2725.322054] nova error:
[ 2725.322057] ERROR: no inode log page available: 1 -28
[ 2725.322057] nova error:
[ 2725.322058] nova_initialize_inode_log ERROR: no inode log page available
[ 2725.322059] nova error:
[ 2725.322060] nova error:
[ 2725.322061] nova_append_file_write_entry failed
[ 2725.322062] nova: nova_cow_file_write: append inode entry failed
[ 2725.322063] ERROR: no inode log page available: 1 -28
[ 2725.322064] nova error:
[ 2725.322065] nova_initialize_inode_log ERROR: no inode log page available
[ 2725.322065] nova error:
[ 2725.322066] nova_append_file_write_entry failed
[ 2725.322066] nova: nova_cow_file_write: append inode entry failed
[ 2725.322068] nova error:
[ 2725.322069] ERROR: no inode log page available: 1 -28
[ 2725.322070] nova error:
[ 2725.322071] nova_initialize_inode_log ERROR: no inode log page available
[ 2725.322071] nova error:
[ 2725.322071] nova_append_file_write_entry failed
[ 2725.322072] nova: nova_cow_file_write: append inode entry failed
[ 2725.322074] nova error:
[ 2725.322075] ERROR: no inode log page available: 1 -28
[ 2725.322076] nova error:
[ 2725.322077] nova_initialize_inode_log ERROR: no inode log page available
[ 2725.322077] nova error:
[ 2725.322078] nova_append_file_write_entry failed
[ 2725.322079] nova: nova_cow_file_write: append inode entry failed
[ 2728.385978] drop-caches (26556): drop_caches: 3
[ 2731.949009] nova: Current epoch id: 0
[ 2731.949066] nova error:
[ 2731.949069] ERROR: no inode log page available: 1 -28
[ 2731.949070] nova: Error saving inode list: -28
[ 2731.949070] nova error:
[ 2731.949071] ERROR: no inode log page available: 1 -28
[ 2731.949071] nova: Error saving blocknode mappings: -28
[ 2733.333761] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2733.333763] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2733.333863] nova: Start NOVA snapshot cleaner thread.
[ 2733.333865] nova: creating an empty nova of size 21474836480
[ 2733.333875] nova: Running snapshot cleaner thread
[ 2733.336135] nova: NOVA initialization finish
[ 2733.336145] nova: Current epoch id: 0
[ 2733.391500] drop-caches (26578): drop_caches: 3
[ 2749.268320] nova error:
[ 2749.268322] ERROR: no inode log page available: 1 -28
[ 2749.268323] nova error:
[ 2749.268324] nova_initialize_inode_log ERROR: no inode log page available
[ 2749.268324] nova error:
[ 2749.268325] nova_append_file_write_entry failed
[ 2749.268326] nova: nova_cow_file_write: append inode entry failed
[ 2749.268331] nova error:
[ 2749.268333] ERROR: no inode log page available: 1 -28
[ 2749.268334] nova error:
[ 2749.268335] nova_initialize_inode_log ERROR: no inode log page available
[ 2749.268335] nova error:
[ 2749.268336] nova_append_file_write_entry failed
[ 2749.268336] nova: nova_cow_file_write: append inode entry failed
[ 2751.805447] drop-caches (26605): drop_caches: 3
[ 2755.311343] nova: Current epoch id: 0
[ 2755.311453] nova error:
[ 2755.311455] ERROR: no inode log page available: 1 -28
[ 2755.311456] nova: Error saving inode list: -28
[ 2755.311456] nova error:
[ 2755.311457] ERROR: no inode log page available: 1 -28
[ 2755.311457] nova: Error saving blocknode mappings: -28
[ 2756.925687] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2756.925689] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2756.925850] nova: Start NOVA snapshot cleaner thread.
[ 2756.925852] nova: creating an empty nova of size 21474836480
[ 2756.925876] nova: Running snapshot cleaner thread
[ 2756.928148] nova: NOVA initialization finish
[ 2756.928158] nova: Current epoch id: 0
[ 2756.975251] drop-caches (26627): drop_caches: 3
[ 2775.394442] drop-caches (26651): drop_caches: 3
[ 2778.264496] nova: Current epoch id: 0
[ 2778.264606] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x2d2ede000, tail 0x2d2ede080
[ 2778.264613] nova: nova_save_blocknode_mappings_to_log: 7 blocknodes, 1 log pages, pi head 0x2d2edf000, tail 0x2d2edf070
[ 2779.230753] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2779.230755] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2779.230830] nova: Start NOVA snapshot cleaner thread.
[ 2779.230832] nova: creating an empty nova of size 21474836480
[ 2779.230835] nova: Running snapshot cleaner thread
[ 2779.233162] nova: NOVA initialization finish
[ 2779.233173] nova: Current epoch id: 0
[ 2779.284815] drop-caches (26673): drop_caches: 3
[ 2783.522614] nova: nova_cow_file_write alloc blocks failed -28
[ 2783.522616] nova: nova_cow_file_write alloc blocks failed -28
[ 2783.522617] nova: nova_cow_file_write alloc blocks failed -28
[ 2783.522619] nova: nova_cow_file_write alloc blocks failed -28
[ 2785.002630] nova error:
[ 2785.002633] ERROR: no inode log page available: 256 -28
[ 2785.002634] nova error:
[ 2785.002634] nova_extend_inode_log ERROR: no inode log page available
[ 2785.002635] nova: curr_p 0x3b8823fc0, 36326 pages
[ 2785.002635] nova error:
[ 2785.002636] nova_append_setattr_entry failed
[ 2785.002636] nova: nova_handle_setattr_operation: append setattr entry failure
[ 2785.330585] drop-caches (26698): drop_caches: 3
[ 2785.684623] nova: Current epoch id: 0
[ 2785.684699] nova error:
[ 2785.684700] ERROR: no inode log page available: 1 -28
[ 2785.684701] nova: Error saving inode list: -28
[ 2785.684702] nova error:
[ 2785.684702] ERROR: no inode log page available: 1 -28
[ 2785.684703] nova: Error saving blocknode mappings: -28
[ 2785.746347] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2785.746349] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2785.746472] nova: Start NOVA snapshot cleaner thread.
[ 2785.746475] nova: creating an empty nova of size 21474836480
[ 2785.746482] nova: Running snapshot cleaner thread
[ 2785.748739] nova: NOVA initialization finish
[ 2785.748750] nova: Current epoch id: 0
[ 2785.774429] drop-caches (26720): drop_caches: 3
[ 2793.894362] nova: nova_cow_file_write alloc blocks failed -28
[ 2793.894363] nova: nova_cow_file_write alloc blocks failed -28
[ 2804.367848] drop-caches (26752): drop_caches: 3
[ 2805.407422] nova: Current epoch id: 0
[ 2805.407475] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x13285000, tail 0x13285080
[ 2805.409530] nova: nova_save_blocknode_mappings_to_log: 9569 blocknodes, 38 log pages, pi head 0x13286000, tail 0x132abab0
[ 2805.460200] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2805.460202] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2805.460297] nova: Start NOVA snapshot cleaner thread.
[ 2805.460300] nova: creating an empty nova of size 21474836480
[ 2805.460308] nova: Running snapshot cleaner thread
[ 2805.462428] nova: NOVA initialization finish
[ 2805.462436] nova: Current epoch id: 0
[ 2805.519638] drop-caches (26774): drop_caches: 3
[ 2822.206448] nova: nova_cow_file_write alloc blocks failed -28
[ 2838.835059] drop-caches (26796): drop_caches: 3
[ 2840.055465] nova: Current epoch id: 0
[ 2840.055518] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1327c000, tail 0x1327c080
[ 2840.055589] nova: nova_save_blocknode_mappings_to_log: 323 blocknodes, 2 log pages, pi head 0x1327d000, tail 0x1327e450
[ 2840.099738] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2840.099740] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2840.099821] nova: Start NOVA snapshot cleaner thread.
[ 2840.099823] nova: creating an empty nova of size 21474836480
[ 2840.099831] nova: Running snapshot cleaner thread
[ 2840.101927] nova: NOVA initialization finish
[ 2840.101936] nova: Current epoch id: 0
[ 2840.155346] drop-caches (26818): drop_caches: 3
[ 2859.892227] drop-caches (26847): drop_caches: 3
[ 2861.219713] nova: Current epoch id: 0
[ 2861.219772] nova: nova_save_inode_list_to_log: 39 inode nodes, pi head 0x13283000, tail 0x13283270
[ 2861.219854] nova: nova_save_blocknode_mappings_to_log: 383 blocknodes, 2 log pages, pi head 0x13284000, tail 0x13285810
[ 2861.287898] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2861.287900] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2861.288038] nova: Start NOVA snapshot cleaner thread.
[ 2861.288040] nova: creating an empty nova of size 21474836480
[ 2861.288047] nova: Running snapshot cleaner thread
[ 2861.290149] nova: NOVA initialization finish
[ 2861.290158] nova: Current epoch id: 0
[ 2861.335476] drop-caches (26869): drop_caches: 3
[ 2881.517843] drop-caches (26896): drop_caches: 3
[ 2882.939684] nova: Current epoch id: 0
[ 2882.939750] nova: nova_save_inode_list_to_log: 19 inode nodes, pi head 0x1327c000, tail 0x1327c130
[ 2882.939825] nova: nova_save_blocknode_mappings_to_log: 213 blocknodes, 1 log pages, pi head 0x1327d000, tail 0x1327dd50
[ 2883.021245] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2883.021248] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2883.021382] nova: Start NOVA snapshot cleaner thread.
[ 2883.021386] nova: creating an empty nova of size 21474836480
[ 2883.021391] nova: Running snapshot cleaner thread
[ 2883.023992] nova: NOVA initialization finish
[ 2883.024009] nova: Current epoch id: 0
[ 2883.075468] drop-caches (26918): drop_caches: 3
[ 2902.748827] drop-caches (26944): drop_caches: 3
[ 2904.219493] nova: Current epoch id: 0
[ 2904.219579] nova: nova_save_inode_list_to_log: 15 inode nodes, pi head 0x13286000, tail 0x132860f0
[ 2904.219606] nova: nova_save_blocknode_mappings_to_log: 118 blocknodes, 1 log pages, pi head 0x13287000, tail 0x13287760
[ 2904.288181] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2904.288184] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2904.288283] nova: Start NOVA snapshot cleaner thread.
[ 2904.288285] nova: creating an empty nova of size 21474836480
[ 2904.288293] nova: Running snapshot cleaner thread
[ 2904.290437] nova: NOVA initialization finish
[ 2904.290446] nova: Current epoch id: 0
[ 2904.345080] drop-caches (26966): drop_caches: 3
[ 2921.042869] drop-caches (26999): drop_caches: 3
[ 2922.271483] nova: Current epoch id: 0
[ 2922.271529] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1327e000, tail 0x1327e080
[ 2922.271535] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x1327f000, tail 0x1327f080
[ 2922.344002] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2922.344004] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2922.344153] nova: Start NOVA snapshot cleaner thread.
[ 2922.344156] nova: creating an empty nova of size 21474836480
[ 2922.344163] nova: Running snapshot cleaner thread
[ 2922.346326] nova: NOVA initialization finish
[ 2922.346335] nova: Current epoch id: 0
[ 2922.391796] drop-caches (27021): drop_caches: 3
[ 2938.642862] drop-caches (27048): drop_caches: 3
[ 2940.031474] nova: Current epoch id: 0
[ 2940.031532] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x1327e000, tail 0x1327e080
[ 2940.031538] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x1327f000, tail 0x1327f080
[ 2940.092196] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2940.092198] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2940.092325] nova: Start NOVA snapshot cleaner thread.
[ 2940.092328] nova: creating an empty nova of size 21474836480
[ 2940.092334] nova: Running snapshot cleaner thread
[ 2940.094879] nova: NOVA initialization finish
[ 2940.094895] nova: Current epoch id: 0
[ 2940.157403] drop-caches (27070): drop_caches: 3
[ 2956.617647] drop-caches (27094): drop_caches: 3
[ 2957.951518] nova: Current epoch id: 0
[ 2957.951560] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x13287000, tail 0x13287080
[ 2957.951565] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x13288000, tail 0x13288080
[ 2958.030480] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2958.030482] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2958.030592] nova: Start NOVA snapshot cleaner thread.
[ 2958.030595] nova: creating an empty nova of size 21474836480
[ 2958.030602] nova: Running snapshot cleaner thread
[ 2958.032885] nova: NOVA initialization finish
[ 2958.032895] nova: Current epoch id: 0
[ 2958.144081] drop-caches (27116): drop_caches: 3
[ 2978.882500] drop-caches (2995): drop_caches: 3
[ 2980.183500] nova: Current epoch id: 0
[ 2980.183551] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x144cb000, tail 0x144cb080
[ 2980.183556] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x144cc000, tail 0x144cc080
[ 2980.235850] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 2980.235851] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 2980.235950] nova: Start NOVA snapshot cleaner thread.
[ 2980.235953] nova: creating an empty nova of size 21474836480
[ 2980.235958] nova: Running snapshot cleaner thread
[ 2980.238145] nova: NOVA initialization finish
[ 2980.238155] nova: Current epoch id: 0
[ 2980.281838] drop-caches (3017): drop_caches: 3
[ 3001.177680] drop-caches (11233): drop_caches: 3
[ 3002.551488] nova: Current epoch id: 0
[ 3002.551556] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x144cb000, tail 0x144cb080
[ 3002.551562] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x144cc000, tail 0x144cc080
[ 3002.615808] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 3002.615810] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 3002.615912] nova: Start NOVA snapshot cleaner thread.
[ 3002.615915] nova: creating an empty nova of size 21474836480
[ 3002.615918] nova: Running snapshot cleaner thread
[ 3002.618045] nova: NOVA initialization finish
[ 3002.618055] nova: Current epoch id: 0
[ 3002.669871] drop-caches (11255): drop_caches: 3
[ 3023.368878] drop-caches (19469): drop_caches: 3
[ 3024.563492] nova: Current epoch id: 0
[ 3024.563545] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x144cb000, tail 0x144cb080
[ 3024.563551] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x144cc000, tail 0x144cc080
[ 3024.629555] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 3024.629557] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 3024.629675] nova: Start NOVA snapshot cleaner thread.
[ 3024.629677] nova: creating an empty nova of size 21474836480
[ 3024.629683] nova: Running snapshot cleaner thread
[ 3024.631854] nova: NOVA initialization finish
[ 3024.631865] nova: Current epoch id: 0
[ 3024.694309] drop-caches (19491): drop_caches: 3
[ 3045.510916] drop-caches (27716): drop_caches: 3
[ 3046.895522] nova: Current epoch id: 0
[ 3046.895578] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x293272000, tail 0x293272080
[ 3046.895585] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x293273000, tail 0x293273080
[ 3046.968075] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 3046.968077] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 3046.968166] nova: Start NOVA snapshot cleaner thread.
[ 3046.968169] nova: creating an empty nova of size 21474836480
[ 3046.968172] nova: Running snapshot cleaner thread
[ 3046.970296] nova: NOVA initialization finish
[ 3046.970307] nova: Current epoch id: 0
[ 3047.011819] drop-caches (27738): drop_caches: 3
[ 3067.572487] drop-caches (3615): drop_caches: 3
[ 3068.911516] nova: Current epoch id: 0
[ 3068.911562] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0xb3272000, tail 0xb3272080
[ 3068.911567] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0xb3273000, tail 0xb3273080
[ 3068.989754] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 3068.989756] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 3068.989839] nova: Start NOVA snapshot cleaner thread.
[ 3068.989841] nova: creating an empty nova of size 21474836480
[ 3068.989844] nova: Running snapshot cleaner thread
[ 3068.992106] nova: NOVA initialization finish
[ 3068.992116] nova: Current epoch id: 0
[ 3069.059535] drop-caches (3637): drop_caches: 3
[ 3090.137839] drop-caches (11852): drop_caches: 3
[ 3091.323532] nova: Current epoch id: 0
[ 3091.323603] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x144cb000, tail 0x144cb080
[ 3091.323608] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x144cc000, tail 0x144cc080
[ 3091.378641] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 3091.378643] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 3091.378768] nova: Start NOVA snapshot cleaner thread.
[ 3091.378771] nova: creating an empty nova of size 21474836480
[ 3091.378775] nova: Running snapshot cleaner thread
[ 3091.380990] nova: NOVA initialization finish
[ 3091.381000] nova: Current epoch id: 0
[ 3091.430271] drop-caches (11874): drop_caches: 3
[ 3126.072719] drop-caches (11917): drop_caches: 3
[ 3130.002784] nova: Current epoch id: 0
[ 3130.002858] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x294c72000, tail 0x294c72080
[ 3130.002864] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x294c73000, tail 0x294c73080
[ 3131.706109] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 3131.706111] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 3131.706241] nova: Start NOVA snapshot cleaner thread.
[ 3131.706243] nova: creating an empty nova of size 21474836480
[ 3131.706249] nova: Running snapshot cleaner thread
[ 3131.708522] nova: NOVA initialization finish
[ 3131.708531] nova: Current epoch id: 0
[ 3131.747794] drop-caches (11939): drop_caches: 3
[ 3167.382034] drop-caches (11966): drop_caches: 3
[ 3171.704286] nova: Current epoch id: 0
[ 3171.704340] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x295072000, tail 0x295072080
[ 3171.704345] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x295073000, tail 0x295073080
[ 3173.573120] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 3173.573122] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 3173.573221] nova: Start NOVA snapshot cleaner thread.
[ 3173.573223] nova: creating an empty nova of size 21474836480
[ 3173.573231] nova: Running snapshot cleaner thread
[ 3173.575354] nova: NOVA initialization finish
[ 3173.575363] nova: Current epoch id: 0
[ 3173.616347] drop-caches (11988): drop_caches: 3
[ 3208.947122] drop-caches (12012): drop_caches: 3
[ 3212.968613] nova: Current epoch id: 0
[ 3212.968668] nova: nova_save_inode_list_to_log: 8 inode nodes, pi head 0x294c72000, tail 0x294c72080
[ 3212.968674] nova: nova_save_blocknode_mappings_to_log: 8 blocknodes, 1 log pages, pi head 0x294c73000, tail 0x294c73080
[ 3214.659614] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff95fc00000000, size 21474836480
[ 3214.659616] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 3214.659723] nova: Start NOVA snapshot cleaner thread.
[ 3214.659725] nova: creating an empty nova of size 21474836480
[ 3214.659727] nova: Running snapshot cleaner thread
[ 3214.661861] nova: NOVA initialization finish
[ 3214.661872] nova: Current epoch id: 0
[ 3214.714345] drop-caches (12034): drop_caches: 3
[ 3231.542154] nova: nova_insert_dir_radix_tree ERROR -12: n_dir_rd-0-514432.dat
[ 3231.542156] nova error:
[ 3231.542157] nova_rebuild_handle_dentry ERROR -12
[ 3231.542262] nova: nova_insert_dir_radix_tree ERROR -12: n_dir_rd-0-1084475.dat
[ 3231.542262] nova error:
[ 3231.542263] nova_create return -12

Copied from original issue: NVSL/nova-dev#16

XFSTests generic/426: NOVA opens a deleted file using a file handle

XFSTests generic/401: Nova returns incorrect file type for root inode

NOVA returns the incorrect type for the root inode. Interestingly, stat returns the correct value, but what comes out of dir.c:nova_readdir_fast show i_mode is zero for the root inode.

# xfstests/src/t_dir_type /mnt/ramdisk/ 
. u
.. u
# mkdir /mnt/ramdisk/foo
# xfstests/src/t_dir_type /mnt/ramdisk/foo
. d
.. u 

Infinite assertion failures and/or hang with metadata_csum=1 and replica_metadata=0

With these configuration options, I get a whole system hang. Sometimes w/ and sometimes w/o a bunch of assertion failures on dmesg.

on 84d3e6a, but it it's been present since at least 10142f3.

This happens with

measure_timing=0
inplace_data_updates=0
wprotect=0 
mmap_cow=1      
unsafe_metadata=0     
replica_metadata=0 
metadata_csum=1 
dram_struct_csum=1      
data_csum=1 
data_parity=1

but not

measure_timing=0
inplace_data_updates=0
wprotect=0
mmap_cow=1
unsafe_metadata=0
replica_metadata=0 
metadata_csum=0 ***
dram_struct_csum=1 
data_csum=1 
data_parity=1

# sudo umount /mnt/ramdisk; sudo rmmod nova; sudo modprobe nova measure_timing=0      inplace_data_updates=0      wprotect=0 mmap_cow=1      unsafe_metadata=0     replica_metadata=0 metadata_csum=1 dram_struct_csum=1      data_csum=1 data_parity=1; sudo mount -t NOVA -o init /dev/pmem0 /mnt/ramdisk; echo 1 | sudo tee  /proc/fs/NOVA/pmem0/create_snapshot ;cat /proc/fs/NOVA/pmem0/snapshots
<hangs->

# dmesg
[ 4064.180232] nova: nova_rebuild_dir_inode_tree: unknown type 195, 0x3eee000
[ 4064.181171] nova: nova_rebuild_dir_inode_tree: unknown type 195, 0x3eee000
[ 4064.181208] nova: nova_rebuild_dir_inode_tree: unknown type 195, 0x3eee000
[ 4064.181229] assertion failed fs/nova/rebuild.c:673: 0
[ 4064.181348] nova: nova_rebuild_dir_inode_tree: unknown type 195, 0x3eee000
[ 4064.181386] nova: nova_rebuild_dir_inode_tree: unknown type 195, 0x3eee000
[ 4064.181442] nova: nova_rebuild_dir_inode_tree: unknown type 195, 0x3eee000
[ 4064.181457] nova: nova_rebuild_dir_inode_tree: unknown type 195, 0x3eee000
[ 4064.181508] assertion failed fs/nova/rebuild.c:673: 0
[ 4064.181541] assertion failed fs/nova/rebuild.c:673: 0
[ 4064.181556] nova: nova_rebuild_dir_inode_tree: unknown type 195, 0x3eee000
<...forever...>

XFSTest failures w/ data protection

new failures in devel

• - generic/215
• - generic/285

Failures in common with unprotected mode

• generic/426 #19
• generic/428 #20
• generic/436 #21

XFSTests generic/003: NOVA drops atime precision after remount

For this part of test generic/003

https://github.com/NVSL/xfstests/blob/master/tests/generic/003#L113

atime before remount:
2017-07-01 05:51:51.308508486 +0000

atime after remount:
2017-07-01 05:51:51.000000000 +0000

Similar behavior here:

https://github.com/NVSL/xfstests/blob/master/tests/generic/003#L201

The reason is that nova's persistent inode doesn't store the nanoseconds in the timespec:

https://github.com/NVSL/linux-nova/blob/master/fs/nova/nova_def.h#L87

Journal and snapshot related nvmm data are not replicated

We haven't implemented replication for them and so if their data is corrupted nova couldn't repair. Since these data are not heavily used during nova normal operation, it shouldn't much affect the performance evaluation we have so far.

Snapshots fail with replica_metadata=1 metadata_csum=1

I haven't check which flag breaks it exactly, but this should work.

# sudo modprobe nova measure_timing=0      inplace_data_updates=0      wprotect=0 mmap_cow=1      unsafe_metadata=0     replica_metadata=0 metadata_csum=0 dram_struct_csum=1      data_csum=1 data_parity=1
# mount -t NOVA -o init /dev/pmem0 /mnt/ramdisk
# echo 1 | sudo tee  /proc/fs/NOVA/pmem0/create_snapshot ;cat /proc/fs/NOVA/pmem0/snapshots
========== NOVA snapshot table ==========
Epoch ID	      Date	    Time
       0	2017-07-05	06:54:51
=========== Total 1 snapshots ===========

#  sudo modprobe nova measure_timing=0      inplace_data_updates=0      wprotect=0 mmap_cow=1      unsafe_metadata=0     replica_metadata=1 metadata_csum=1 dram_struct_csum=1      data_csum=1 data_parity=1
# sudo mount -t NOVA -o init /dev/pmem0 /mnt/ramdisk
# echo 1 | sudo tee  /proc/fs/NOVA/pmem0/create_snapshot ;cat /proc/fs/NOVA/pmem0/snapshots
========== NOVA snapshot table ==========
Epoch ID	      Date	    Time
=========== Total 0 snapshots ===========
# dmesg | tail -10
[ 3578.515796] nova: creating an empty nova of size 1073741824
[ 3578.515861] nova: Running snapshot cleaner thread
[ 3578.516253] nova: NOVA initialization finish
[ 3578.516260] nova: Current epoch id: 0
[ 3581.185012] nova: nova_create_snapshot: epoch id 0
[ 3581.185015] nova error:
[ 3581.185016] nova_check_inode_integrity: both inode and its replica fail checksum verification
[ 3581.185017] nova error:
[ 3581.185017] nova_check_inode_integrity: unable to repair inode errors
[ 3581.185018] nova: nova_append_snapshot_info_log: append snapshot info entry failure

XFSTests generic/003: failures with data protection enabled

#    sudo modprobe nova measure_timing=0 \
	 inplace_data_updates=0 \
	 wprotect=0 mmap_cow=1 \
	 unsafe_metadata=0 \
	 replica_metadata=1 metadata_csum=1 dram_struct_csum=1 \
	 data_csum=1 data_parity=1

[ 1667.446838] nova: nova_check_inode_integrity: inode 34 checksum error, trying to repair using the replica
[ 1667.446840] nova: nova_repair_inode: inode 34 error repaired
[ 1667.446842] nova: nova_get_entry_copy: unknown or unsupported entry type (0) for checksum, 0xffff8c4687bd4000
[ 1667.446844] CPU: 1 PID: 30790 Comm: rm Tainted: G    B      OE   4.10.0-nova #8
[ 1667.446845] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[ 1667.446845] Call Trace:
[ 1667.446850]  dump_stack+0x63/0x81
[ 1667.446856]  nova_get_entry_copy.isra.7+0x25d/0x330 [nova]
[ 1667.446859]  nova_verify_entry_csum+0x88/0x440 [nova]
[ 1667.446862]  ? nova_verify_entry_csum+0x297/0x440 [nova]
[ 1667.446863]  ? put_dec+0x18/0xa0
[ 1667.446864]  ? number+0x2ed/0x300
[ 1667.446868]  nova_rebuild_file_inode_tree+0xed/0x5e0 [nova]
[ 1667.446870]  ? printk+0x57/0x73
[ 1667.446874]  ? nova_repair_inode+0xbf/0xe1 [nova]
[ 1667.446877]  ? nova_check_inode_integrity+0x53d/0x620 [nova]
[ 1667.446880]  nova_rebuild_inode+0x15a/0x210 [nova]
[ 1667.446883]  nova_iget+0xa7/0x190 [nova]
[ 1667.446886]  nova_lookup+0xd6/0x1a0 [nova]
[ 1667.446887]  ? legitimize_path.isra.27+0x2e/0x60
[ 1667.446889]  lookup_slow+0xa5/0x160
[ 1667.446890]  walk_component+0x1bf/0x350
[ 1667.446891]  path_lookupat+0x4b/0x100
[ 1667.446892]  filename_lookup+0xb1/0x180
[ 1667.446894]  ? mem_cgroup_commit_charge+0x7e/0x510
[ 1667.446895]  ? __check_object_size+0x100/0x1d7
[ 1667.446897]  ? strncpy_from_user+0x4d/0x170
[ 1667.446898]  user_path_at_empty+0x36/0x40
[ 1667.446899]  vfs_fstatat+0x66/0xc0
[ 1667.446900]  SYSC_newfstatat+0x24/0x60
[ 1667.446901]  ? __do_page_fault+0x2ab/0x520
[ 1667.446902]  SyS_newfstatat+0xe/0x10
[ 1667.446904]  entry_SYSCALL_64_fastpath+0x1e/0xad
[ 1667.446905] RIP: 0033:0x7f3edeca43cb
[ 1667.446905] RSP: 002b:00007fff0cc22918 EFLAGS: 00000246 ORIG_RAX: 0000000000000106
[ 1667.446907] RAX: ffffffffffffffda RBX: 000055c2aaaba0e0 RCX: 00007f3edeca43cb
[ 1667.446907] RDX: 000055c2aaabb398 RSI: 000055c2aaabb428 RDI: ffffffffffffff9c
[ 1667.446908] RBP: 00007f3edef6db00 R08: 0000000000000100 R09: 0000000000000130
[ 1667.446908] R10: 0000000000000100 R11: 0000000000000246 R12: 00007f3edef6db58
[ 1667.446908] R13: 00007fff0cc22bf8 R14: 0000000000002710 R15: 0000000000001110
[ 1667.446911] nova: nova_repair_entry_pr: entry media error repaired
[ 1667.446952] nova error:
[ 1667.446953] File inode 34 log is NULL!
[ 1667.446973] ------------[ cut here ]------------
[ 1667.448047] kernel BUG at fs/nova/rebuild.c:426!
[ 1667.449102] invalid opcode: 0000 [#1] SMP
[ 1667.449995] Modules linked in: nova(OE) libcrc32c rfcomm coretemp crct10dif_pclmul vmw_balloon crc32_pclmul ghash_clmulni_intel pcbc aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf nd_pmem snd_ens1371 gameport snd_ac97_codec ac97_bus dax_pmem dax nd_btt snd_pcm joydev input_leds serio_raw snd_seq_midi snd_seq_midi_event snd_rawmidi snd_seq uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 snd_timer videobuf2_core snd_seq_device videodev media snd soundcore bnep vmw_vsock_vmci_transport vsock vmw_vmci shpchp i2c_piix4 nfit mac_hid btusb btrtl btbcm btintel bluetooth parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse mptspi scsi_transport_spi mptscsih vmwgfx e1000 drm_kms_helper syscopyarea sysfillrect ahci sysimgblt fb_sys_fops libahci
[ 1667.463739]  ttm mptbase drm pata_acpi fjes [last unloaded: nova]
[ 1667.464871] CPU: 1 PID: 30790 Comm: rm Tainted: G    B      OE   4.10.0-nova #8
[ 1667.466222] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[ 1667.468194] task: ffff8c46dcb9ad00 task.stack: ffffba895151c000
[ 1667.469299] RIP: 0010:nova_rebuild_file_inode_tree+0x5a0/0x5e0 [nova]
[ 1667.470493] RSP: 0018:ffffba895151f8c0 EFLAGS: 00010286
[ 1667.471466] RAX: 0000000000000000 RBX: ffff8c46f4496100 RCX: 0000000000000006
[ 1667.472782] RDX: 0000000000000007 RSI: 0000000000000247 RDI: ffff8c46f724dc80
[ 1667.474116] RBP: ffffba895151faa8 R08: 0000000000000001 R09: 000000000060e942
[ 1667.475472] R10: 0000000000000004 R11: 0000000000000000 R12: ffff8c46e6b04800
[ 1667.476797] R13: ffff8c4687bd4400 R14: ffffba895151f948 R15: 0000000000000000
[ 1667.478601] FS:  00007f3edf179700(0000) GS:ffff8c46f7240000(0000) knlGS:0000000000000000
[ 1667.480122] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1667.481196] CR2: 000055c2aaabb1f8 CR3: 000000023e66f000 CR4: 00000000003406e0
[ 1667.482586] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 1667.483992] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 1667.485395] Call Trace:
[ 1667.485908]  ? nova_repair_inode+0xbf/0xe1 [nova]
[ 1667.486837]  ? nova_check_inode_integrity+0x53d/0x620 [nova]
[ 1667.487924]  nova_rebuild_inode+0x15a/0x210 [nova]
[ 1667.488827]  nova_iget+0xa7/0x190 [nova]
[ 1667.489573]  nova_lookup+0xd6/0x1a0 [nova]
[ 1667.490348]  ? legitimize_path.isra.27+0x2e/0x60
[ 1667.491216]  lookup_slow+0xa5/0x160
[ 1667.491880]  walk_component+0x1bf/0x350
[ 1667.492607]  path_lookupat+0x4b/0x100
[ 1667.493304]  filename_lookup+0xb1/0x180
[ 1667.494031]  ? mem_cgroup_commit_charge+0x7e/0x510
[ 1667.494932]  ? __check_object_size+0x100/0x1d7
[ 1667.495770]  ? strncpy_from_user+0x4d/0x170
[ 1667.496582]  user_path_at_empty+0x36/0x40
[ 1667.497342]  vfs_fstatat+0x66/0xc0
[ 1667.497992]  SYSC_newfstatat+0x24/0x60
[ 1667.498704]  ? __do_page_fault+0x2ab/0x520
[ 1667.499478]  SyS_newfstatat+0xe/0x10
[ 1667.500158]  entry_SYSCALL_64_fastpath+0x1e/0xad
[ 1667.501029] RIP: 0033:0x7f3edeca43cb
[ 1667.501712] RSP: 002b:00007fff0cc22918 EFLAGS: 00000246 ORIG_RAX: 0000000000000106
[ 1667.503117] RAX: ffffffffffffffda RBX: 000055c2aaaba0e0 RCX: 00007f3edeca43cb
[ 1667.504446] RDX: 000055c2aaabb398 RSI: 000055c2aaabb428 RDI: ffffffffffffff9c
[ 1667.505770] RBP: 00007f3edef6db00 R08: 0000000000000100 R09: 0000000000000130
[ 1667.507094] R10: 0000000000000100 R11: 0000000000000246 R12: 00007f3edef6db58
[ 1667.508421] R13: 00007fff0cc22bf8 R14: 0000000000002710 R15: 0000000000001110
[ 1667.509749] Code: 40 fe ff ff e8 62 1b 48 d3 48 8b 95 40 fe ff ff e9 e8 fa ff ff 48 8b 95 20 fe ff ff 48 c7 c6 c0 00 89 c0 4c 89 e7 e8 c0 5a 00 00 <0f> 0b e8 29 f3 ff ff 48 8b b5 20 fe ff ff 48 c7 c7 50 cf 88 c0
[ 1667.513215] RIP: nova_rebuild_file_inode_tree+0x5a0/0x5e0 [nova] RSP: ffffba895151f8c0
[ 1667.514726] ---[ end trace 78976917f1fdd30d ]---

XFStests generic/306 failure: mount -o remount,ro /mnt/ramdisk fails

generic/306 dies early because remounting the file system read-only fails.

To replicate:

#sudo mount -t NOVA  /dev/pmem0  /mnt/ramdisk/
#sudo sudo mount -t NOVA -o ro,remount /mnt/ramdisk/
mount: /mnt/ramdisk not mounted or bad option

       In some cases useful info is found in syslog - try
       dmesg | tail or so.
# dmesg|tail
[ 5646.430784] nova: nova_save_blocknode_mappings_to_log: 499 blocknodes, 2 log pages, pi head 0x154205000, tail 0x154206f50
[ 5653.683176] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x280000000, virt_addr ffff8de0c0000000, size 21474836480
[ 5653.683178] nova: measure timing 0, replica metadata 1, metadata checksum 1, inplace metadata update 1, inplace update 0, wprotect 0, mmap Cow 1, data checksum 1, data parity 1, DRAM checksum 1
[ 5653.683315] nova: Start NOVA snapshot cleaner thread.
[ 5653.683336] nova: Running snapshot cleaner thread
[ 5653.683427] nova: nova_init_inode_list_from_inode: 17 inode nodes
[ 5653.683428] nova: Recovered 0 snapshots, latest epoch ID 0
[ 5653.683429] nova: NOVA: Normal shutdown
[ 5653.684044] nova: Current epoch id: 0
[ 5732.099181] Bad mount option: "physaddr=0x0000000280000000"

However

#sudo mount -t NOVA  /dev/pmem0  /mnt/ramdisk/
#sudo sudo mount -t NOVA -o ro,remount /dev/pmem0 /mnt/ramdisk/

works fine.

XFSTests generic/215: mtime and ctime not updated for mmap'd accesses

See #25

LTP ftest08 fails intermittently

<<<test_start>>>
tag=ftest08 stime=1500358363
cmdline="ftest08"
contacts=""
analysis=exit
<<<test_output>>>
ftest08     1  TFAIL  :  ftest08.c:361: 	Test[2]: xfr=1152 != 2048, zero read.
ftest08     1  TFAIL  :  ftest08.c:190: 	Expected 0 exit status - failed.
ftest08     2  TFAIL  :  ftest08.c:105: Test failed.
<<<execution_status>>>
initiation_status="ok"
duration=9 termination_type=exited termination_id=1 corefile=no
cutime=4 cstime=177
<<<test_end>>>
<<<test_start>>>

XFSTests generic/426 fails with data protection.

swanson@swanson:~/nova-testscripts/nova-ci$ list_module_args nova
nova
data_csum=0
data_parity=0
dram_struct_csum=0
inplace_data_updates=0
measure_timing=0
metadata_csum=0
mmap_cow=1
unsafe_metadata=0
wprotect=0
swanson@swanson:~/nova-testscripts/nova-ci$ ./run_tests.sh xfstests generic/426
...
    +++ /home/swanson/nova-testscripts/nova-ci/xfstests/xfstests/results//generic/426.out.bad	2017-07-11 09:47:14.243854365 -0700
    @@ -1,2 +1,3 @@
     QA output created by 426
    +open_by_handle(1023) opened an unlinked file!
     Silence is golden
    ...
    (Run 'diff -u tests/generic/426.out /home/swanson/nova-testscripts/nova-ci/xfstests/xfstests/results//generic/426.out.bad'  to see the entire diff)
Ran: generic/426
Failures: generic/426
Failed 1 of 1 tests

Detect MCEs during journal integrity check.

umount fails because of stale loopback during interrupted run of ltp.

To reproduce, mount NOVA fs on /mnt/ramdisk

Then run

 /opt/ltp/runltp -f nova -d /mnt/ramdisk

and hit ctrl-C after a while. Try to unmount:

umount /mnt/ramdisk

if fails, try

losetup -d /dev/loop*
umount /mnt/ramdisk

If fails, that's the bug.

This shows up on console:

[ 32.256504] Oops: 0010 [#1] SMP
[ 32.257489] Modules linked in: nova(OE) libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc aesni_intel vmw_balloon aes_x86_64 crypto_simd dax_pmem cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm snd_seq_midi snd_seq_midi_event joydev input_leds uvcvideo dax serio_raw snd_rawmidi nd_pmem nd_btt videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core videodev snd_seq snd_timer snd_seq_device btusb btrtl media btbcm btintel bluetooth snd soundcore nfit vmw_vsock_vmci_transport vsock shpchp i2c_piix4 vmw_vmci mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse vmwgfx drm_kms_helper ahci syscopyarea libahci sysfillrect e1000 sysimgblt fb_sys_fops ttm mptspi drm scsi_transport_spi
[ 32.279592] mptscsih pata_acpi mptbase fjes
[ 32.280914] CPU: 0 PID: 2746 Comm: loop0 Tainted: G OE 4.10.0-nova #8
[ 32.282976] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[ 32.285974] task: ffff995cc760da00 task.stack: ffffbca844b40000
[ 32.287649] RIP: 0010: (null)
[ 32.288838] RSP: 0018:ffffbca844b43d20 EFLAGS: 00010246
[ 32.290605] RAX: ffffffffc067ca80 RBX: ffff995cf3043fc0 RCX: 0000000000000001
[ 32.292616] RDX: ffff995cce468888 RSI: ffffbca844b43d68 RDI: ffff995cf3043fc0
[ 32.294925] RBP: ffffbca844b43dc0 R08: 0000000000001000 R09: ffff995cf3043f78
[ 32.297431] R10: 0000000000001000 R11: ffff995cce468888 R12: 0000000000000000
[ 32.300188] R13: 0000000000000000 R14: ffff995cce468888 R15: 0000000000000001
[ 32.302801] FS: 0000000000000000(0000) GS:ffff995cf9600000(0000) knlGS:0000000000000000
[ 32.305722] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 32.307547] CR2: 0000000000000000 CR3: 00000000add03000 CR4: 00000000003406f0
[ 32.309893] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 32.311959] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 32.314002] Call Trace:
[ 32.314736] ? lo_rw_aio+0x13c/0x290
[ 32.315726] ? update_curr+0xf3/0x170
[ 32.316810] loop_queue_work+0x938/0xac0
[ 32.317946] ? pick_next_task_fair+0x10d/0x4b0
[ 32.319171] ? __switch_to+0x23c/0x520
[ 32.320217] ? __schedule+0x230/0x6b0
[ 32.321295] kthread_worker_fn+0xf6/0x1c0
[ 32.322487] kthread+0x101/0x140
[ 32.323504] ? kthread_create_worker_on_cpu+0x70/0x70
[ 32.325156] ? kthread_create_on_node+0x60/0x60
[ 32.326747] ret_from_fork+0x2c/0x40
[ 32.327882] Code: Bad RIP value.
[ 32.328856] RIP: (null) RSP: ffffbca844b43d20
[ 32.330487] CR2: 0000000000000000
[ 32.331366] ---[ end trace c3c35d5ea58174ef ]---

atime and mmaptime xfstests fail

Add CPU Hotplug support

Mounted snapshots are not read-only.

Currently, if you mount a snapshot and modify it, the changes appear in the current FS image.

Snapshot mounts should be read-only.

Added test xfstests: nova/002

Process and recover poison sectors on mount.

From @stevenjswanson on April 21, 2017 17:23

Copied from original issue: NVSL/nova-dev#10

Scrub data and metadata

From @stevenjswanson on April 21, 2017 17:23

Copied from original issue: NVSL/nova-dev#9

XFSTests generic/215

Add support for quotas.

Protect snapshot log in DRAM.

From @stevenjswanson on April 21, 2017 17:23

Copied from original issue: NVSL/nova-dev#11

XFStests generic/192: atime not updated

See #23

System crashes after creating loopback device after mounting nova

To reproduce, checkout nova-testscripts, then

# cd nova-testscripts/nova-ci
# bash crashers/001.sh

Example Dmesg

[  157.169105] IP: free_pcppages_bulk+0x107/0x4c0
[  157.169978] PGD 0

[  157.170706] Oops: 0002 [#1] SMP
[  157.171334] Modules linked in: nova(OE) libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc vmw_balloon aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm joydev snd_seq_midi snd_seq_midi_event uvcvideo snd_rawmidi input_leds nd_pmem nd_btt dax_pmem dax serio_raw videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core snd_seq videodev btusb btrtl btbcm media snd_timer btintel snd_seq_device bluetooth snd soundcore i2c_piix4 shpchp nfit vmw_vsock_vmci_transport vsock vmw_vmci mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse vmwgfx mptspi scsi_transport_spi mptscsih drm_kms_helper syscopyarea sysfillrect sysimgblt ahci fb_sys_fops libahci ttm
[  157.186255]  mptbase e1000 drm pata_acpi fjes
[  157.187182] CPU: 1 PID: 18598 Comm: growfiles Tainted: G           OE   4.10.0-nova #8
[  157.188963] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  157.191338] task: ffff955faf145a00 task.stack: ffffb1f90597c000
[  157.192723] RIP: 0010:free_pcppages_bulk+0x107/0x4c0
[  157.193816] RSP: 0018:ffffb1f90597fa08 EFLAGS: 00010046
[  157.194946] RAX: 0000000000000000 RBX: ffffdfc148be33e0 RCX: 0000000000000020
[  157.196440] RDX: ffff955fb965d0d8 RSI: ffff955fb965d0c8 RDI: ffffdfc1481cad60
[  157.198088] RBP: ffffb1f90597fa80 R08: ffff955fbffd3de0 R09: 0000000000000000
[  157.199537] R10: 0000000000000001 R11: 00000000000002b4 R12: ffffdfc148be33c0
[  157.201080] R13: dead000000000100 R14: ffff955fbffd3d00 R15: ffff955fbffd3d00
[  157.202576] FS:  0000000000000000(0000) GS:ffff955fb9640000(0000) knlGS:0000000000000000
[  157.204312] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  157.205527] CR2: 0000000000000000 CR3: 000000003c209000 CR4: 00000000003406e0
[  157.207021] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  157.208492] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  157.210039] Call Trace:
[  157.210548]  free_hot_cold_page+0x232/0x260
[  157.211418]  free_hot_cold_page_list+0x3f/0xa0
[  157.212521]  release_pages+0x2b9/0x360
[  157.213311]  free_pages_and_swap_cache+0x9b/0xb0
[  157.214286]  tlb_flush_mmu_free+0x36/0x60
[  157.215126]  tlb_finish_mmu+0x1c/0x50
[  157.215882]  exit_mmap+0xd6/0x170
[  157.216574]  mmput+0x57/0x130
[  157.217193]  do_exit+0x273/0xb00
[  157.217869]  do_group_exit+0x43/0xb0
[  157.218583]  get_signal+0x289/0x630
[  157.219285]  do_signal+0x37/0x740
[  157.219989]  ? group_send_sig_info+0x35/0x40
[  157.220849]  ? __check_object_size+0x100/0x1d7
[  157.221784]  exit_to_usermode_loop+0x71/0xa0
[  157.222635]  syscall_return_slowpath+0x59/0x60
[  157.223507]  entry_SYSCALL_64_fastpath+0xab/0xad
[  157.224394] RIP: 0033:0x7fcba53fe8b9
[  157.225095] RSP: 002b:00007fcba5a37e60 EFLAGS: 00000206 ORIG_RAX: 00000000000000ca
[  157.226542] RAX: fffffffffffffdfc RBX: 00005556b3a31e48 RCX: 00007fcba53fe8b9
[  157.227896] RDX: 000000000000031f RSI: 0000000000000189 RDI: 00007fcba5816284
[  157.229206] RBP: 0000000000000000 R08: 00007fcba58161e0 R09: 00000000ffffffff
[  157.230515] R10: 00007fcba5a37ee0 R11: 0000000000000206 R12: 000000000000031f
[  157.231864] R13: 00007fcba5a37ee0 R14: ffffffffffffff92 R15: 00007ffe47776d00
[  157.233176] Code: 48 83 c0 01 48 c1 e0 04 48 01 f0 48 89 45 a8 48 8b 45 a8 48 83 7d 90 00 48 8b 58 08 48 8b 43 08 48 8b 13 4c 8d 63 e0 48 89 42 08 <48> 89 10 48 b8 00 02 00 00 00 00 ad de 4c 89 2b 48 89 43 08 4c
[  157.236607] RIP: free_pcppages_bulk+0x107/0x4c0 RSP: ffffb1f90597fa08
[  157.237794] CR2: 0000000000000000
[  157.238420] ---[ end trace 061ca857e0ddc4ad ]---
[  157.239279] Fixing recursive fault but reboot is needed!

XFSTests generic/285: lseek misbehaves(?) in the presence of holes.

This is probably related to #21.

This functions creates a file with a hole at the end, and checks the behavior of SEEK_HOLE

https://github.com/NVSL/xfstests/blob/master/src/seek_sanity_test.c#L160

It finds that pos != filsz, which it reported the presence of the hole and only seeked past the first two blocks.

This function
https://github.com/NVSL/xfstests/blob/master/src/seek_sanity_test.c#L903

called from here:

https://github.com/NVSL/xfstests/blob/master/src/seek_sanity_test.c#L614

creates a file with the hole at the beginning and then tests SEEK_DATA, which ignores the hole and acts as if the space is allocated.

XFSTests generic/436: lseek misbehaves(?) in the presence of holes.

Probably related to #22.

The problem may be with the test. xfstests/src/seek_sanity_test.c does a simple check to see whether SEEK_HOLE and SEEK_DATA should actually report the locations of holes and data (it sets the default_behavior flag, if it does not.

If they should report actual hole location, the test is particular about where the holes should be. It seems that NOVA's behavior is allowed by the lseek manpage's description of SEEK_DATA and SEEK_HOLE.

Decide which options should be mkfs-time, mount-time, module load-time, and per-file

My thoughts:

• metadata_csum: mkfs-time
• data_csum: mkfs-time
• data_parity: mkfs-time
• wprotect: mount-time
• inplace_data_updates: mount-time, per-file

XFSTests generic/428: writes to dax-mmapped pages don't work

Currently NOVA does not support writing to pages that mmap'd.

We have a fix for this that involves page faults. It is not fast, but we expect this case to be rare.

We have not implemented the fix because of some locking issue.

@Andiry can explain the locking problem in more detail.

Mounting pmem devices without a NOVA fs causes kernel Oops

If you try to mount a pmem devices that has not been formatted with an NOVA fs, you get the following Oops:

[ 141.745336] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x200000000, virt_addr ffffa0d000000000, size 23622320128
[ 141.745344] nova: measure timing 0, metadata checksum 0, inplace update 0, wprotect 0, data checksum 0, data parity 0, DRAM checksum 0
[ 141.745429] nova: Start NOVA snapshot cleaner thread.
[ 141.745436] nova: Running snapshot cleaner thread
[ 141.745437] nova error:
[ 141.745438] Can't find a valid nova partition
[ 141.745439] nova: Memory contains invalid nova 0:4e4f5641
[ 141.745448] BUG: unable to handle kernel NULL pointer dereference at 0000000000000068
[ 141.745454] IP: mount_fs+0x43/0x140
[ 141.745455] PGD 0
[ 141.745456] P4D 0

[ 141.745457] Oops: 0000 [#1] SMP
[ 141.745459] Modules linked in: nova ip6table_filter ip6_tables iptable_filter nls_iso8859_1 input_leds serio_raw pvpanic ib_iser rdma_cm configfs iw_cm ib_cm ib_core iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi parport_pc ppdev parport ip_tables x_tables autofs4 btrfs raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multipath linear crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc aesni_intel aes_x86_64 crypto_simd cryptd glue_helper psmouse virtio_net virtio_scsi
[ 141.745484] CPU: 2 PID: 32702 Comm: mount Not tainted 4.12.0-nova #1

Not all direct loads from nvmm are avoided

To trap media errors NOVA would like to read nvmm (meta)data in to dram using machine-check-safe functions such as memcpy_mcsafe(), or its wrapper memcpy_from_pmem(), and then consume the copied and verified data in dram. Reading file data should be totally covered by memcpy_from_pmem(), and most reads of metadata are also covered but not all, because that will cause changes to many function interfaces.

Functions like nova_verify_entry_csum() and nova_check_inode_integrity will obtain a relevant metadata copy in dram and verify its integrity. Therefore it's possible to use the copy for subsequent functions that read the metadata. Now NOVA's implementation simply passes two pointers (one to nvmm, one to dram) around functions. Refer to how "entry" and "entryc" (entry_copy) are used.

However it's awkward and error-prone to always pass two pointers to every function, and perhaps a better solution is to add a nvmm pointer field to the NOVA metadata structures, for example:

struct nova_abc_entry {
        __le64 type;
        __le64 a;
        __le64 b;
        __le32 c;
        __le32 csum;
        __le64 addr; /* offset address in nvmm */
} __attribute((__packed__));

Once the structure is copied to dram and verified in a caller function, it can pass a pointer to the dram structure (just use one pointer as NOVA has been doing) to its callees, and if any callee wants to use the nvmm address, it can use the 'addr' field.

Known places that still directly read from nvmm are:

1. Read entry values in nova_execute_invalidate_reassign_logentry(), of log.c.
2. Use of entry values in nova_calc_entry_csum().
3. Use of inode values in nova_check_inode_checksum().
4. Read entry values in journal.c and snapshot.c.
5. Read pi-> values in bbuild.c, gc.c and inode.c

Frequent, non-deterministic failures with data protection on XFStests and LTP

swanson@swanson:~/nova-testscripts/nova-ci/results$ list_module_args nova
nova
data_csum=1
data_parity=1
dram_struct_csum=1
inplace_data_updates=0
measure_timing=0
metadata_csum=1
mmap_cow=1
replica_metadata=1
unsafe_metadata=0
wprotect=0

Example Dmesg

[  157.169105] IP: free_pcppages_bulk+0x107/0x4c0
[  157.169978] PGD 0

[  157.170706] Oops: 0002 [#1] SMP
[  157.171334] Modules linked in: nova(OE) libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc vmw_balloon aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm joydev snd_seq_midi snd_seq_midi_event uvcvideo snd_rawmidi input_leds nd_pmem nd_btt dax_pmem dax serio_raw videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core snd_seq videodev btusb btrtl btbcm media snd_timer btintel snd_seq_device bluetooth snd soundcore i2c_piix4 shpchp nfit vmw_vsock_vmci_transport vsock vmw_vmci mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse vmwgfx mptspi scsi_transport_spi mptscsih drm_kms_helper syscopyarea sysfillrect sysimgblt ahci fb_sys_fops libahci ttm
[  157.186255]  mptbase e1000 drm pata_acpi fjes
[  157.187182] CPU: 1 PID: 18598 Comm: growfiles Tainted: G           OE   4.10.0-nova #8
[  157.188963] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  157.191338] task: ffff955faf145a00 task.stack: ffffb1f90597c000
[  157.192723] RIP: 0010:free_pcppages_bulk+0x107/0x4c0
[  157.193816] RSP: 0018:ffffb1f90597fa08 EFLAGS: 00010046
[  157.194946] RAX: 0000000000000000 RBX: ffffdfc148be33e0 RCX: 0000000000000020
[  157.196440] RDX: ffff955fb965d0d8 RSI: ffff955fb965d0c8 RDI: ffffdfc1481cad60
[  157.198088] RBP: ffffb1f90597fa80 R08: ffff955fbffd3de0 R09: 0000000000000000
[  157.199537] R10: 0000000000000001 R11: 00000000000002b4 R12: ffffdfc148be33c0
[  157.201080] R13: dead000000000100 R14: ffff955fbffd3d00 R15: ffff955fbffd3d00
[  157.202576] FS:  0000000000000000(0000) GS:ffff955fb9640000(0000) knlGS:0000000000000000
[  157.204312] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  157.205527] CR2: 0000000000000000 CR3: 000000003c209000 CR4: 00000000003406e0
[  157.207021] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  157.208492] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  157.210039] Call Trace:
[  157.210548]  free_hot_cold_page+0x232/0x260
[  157.211418]  free_hot_cold_page_list+0x3f/0xa0
[  157.212521]  release_pages+0x2b9/0x360
[  157.213311]  free_pages_and_swap_cache+0x9b/0xb0
[  157.214286]  tlb_flush_mmu_free+0x36/0x60
[  157.215126]  tlb_finish_mmu+0x1c/0x50
[  157.215882]  exit_mmap+0xd6/0x170
[  157.216574]  mmput+0x57/0x130
[  157.217193]  do_exit+0x273/0xb00
[  157.217869]  do_group_exit+0x43/0xb0
[  157.218583]  get_signal+0x289/0x630
[  157.219285]  do_signal+0x37/0x740
[  157.219989]  ? group_send_sig_info+0x35/0x40
[  157.220849]  ? __check_object_size+0x100/0x1d7
[  157.221784]  exit_to_usermode_loop+0x71/0xa0
[  157.222635]  syscall_return_slowpath+0x59/0x60
[  157.223507]  entry_SYSCALL_64_fastpath+0xab/0xad
[  157.224394] RIP: 0033:0x7fcba53fe8b9
[  157.225095] RSP: 002b:00007fcba5a37e60 EFLAGS: 00000206 ORIG_RAX: 00000000000000ca
[  157.226542] RAX: fffffffffffffdfc RBX: 00005556b3a31e48 RCX: 00007fcba53fe8b9
[  157.227896] RDX: 000000000000031f RSI: 0000000000000189 RDI: 00007fcba5816284
[  157.229206] RBP: 0000000000000000 R08: 00007fcba58161e0 R09: 00000000ffffffff
[  157.230515] R10: 00007fcba5a37ee0 R11: 0000000000000206 R12: 000000000000031f
[  157.231864] R13: 00007fcba5a37ee0 R14: ffffffffffffff92 R15: 00007ffe47776d00
[  157.233176] Code: 48 83 c0 01 48 c1 e0 04 48 01 f0 48 89 45 a8 48 8b 45 a8 48 83 7d 90 00 48 8b 58 08 48 8b 43 08 48 8b 13 4c 8d 63 e0 48 89 42 08 <48> 89 10 48 b8 00 02 00 00 00 00 ad de 4c 89 2b 48 89 43 08 4c
[  157.236607] RIP: free_pcppages_bulk+0x107/0x4c0 RSP: ffffb1f90597fa08
[  157.237794] CR2: 0000000000000000
[  157.238420] ---[ end trace 061ca857e0ddc4ad ]---
[  157.239279] Fixing recursive fault but reboot is needed!

XFStests generic/424: Fails for kernel 4.12.

chattr doesn't fail when setting extended attrs and also doesn't properly set them.

THis at least causes the 424 to fail, but 424 checks for the presence of statx() before running. chattr uses ioctl.

This may be a problem with xfstests or that I have an old version of chattr installed.

Replicate Journals

Most kernel module command line options should be mount-time options.

Support remounting file systems with different protection mechanisms.

LTP: rwtest03 crashes

Moved to nova-failures in NOVA-ltp.

swanson@hn:~/nova-testscripts/nova-ci$ list_module_args nova
nova
data_csum=0
data_parity=0
dram_struct_csum=0
inplace_data_updates=0
measure_timing=0
metadata_csum=0
mmap_cow=1
unsafe_metadata=0
wprotect=0

Dmesg:

[ 2678.728164] nova: nova_dax_fault: inode 37, pgoff 3082
[ 2678.728164] nova: nova_dax_get_blocks: pgoff 3082, num 1, create 1
[ 2678.728165] nova: nova_fsync: msync pgoff range 0 to 3125
[ 2678.728165] nova: nova_dax_get_blocks: found pgoff 3082, block 34824
[ 2678.728168] nova: nova_dax_fault: inode 37, pgoff 3083
[ 2678.728168] nova: nova_dax_get_blocks: pgoff 3083, num 1, create 1
[ 2678.728169] nova: nova_dax_get_blocks: found pgoff 3083, block 34818
[ 2678.728171] nova: nova_dax_fault: inode 37, pgoff 3084
[ 2678.728171] nova: nova_dax_get_blocks: pgoff 3084, num 1, create 1
[ 2678.728172] nova: nova_dax_get_blocks: found pgoff 3084, block 34819
[ 2678.728175] nova: nova_fsync: msync pgoff range 0 to 3125
[ 2678.728407] nova: [nova_vma_close:1735] MMAP 4KPAGE vm_start(0x7f2033df9000), vm_end(0x7f2034a2e000), vm_flags(0x380000fb), vm_page_prot(0x8000000000000025)
[ 2678.728409] nova: Inode 37 remove vma ffff95315dc775e0, start 0x7f2033df9000, end 0x7f2034a2e000, pgoff 0
[ 2678.728430] nova: [nova_vma_close:1735] MMAP 4KPAGE vm_start(0x7f2033df9000), vm_end(0x7f2034a2e000), vm_flags(0x380000fb), vm_page_prot(0x8000000000000025)
[ 2678.728431] nova: Inode 37 remove vma ffff95315dc74ed8, start 0x7f2033df9000, end 0x7f2034a2e000, pgoff 0
[ 2678.728505] general protection fault: 0000 [#1] SMP
[ 2678.728620] Modules linked in: nova libcrc32c rfcomm vmw_balloon coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel snd_ens1371 gameport snd_ac97_codec ac97_bus pcbc aesni_intel snd_pcm aes_x86_64 snd_seq_midi crypto_simd snd_seq_midi_event cryptd glue_helper intel_rapl_perf snd_rawmidi bnep snd_seq joydev vmw_vsock_vmci_transport nd_pmem vsock uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 input_leds dax_pmem nd_btt dax serio_raw videobuf2_core videodev media snd_timer snd_seq_device snd soundcore i2c_piix4 vmw_vmci shpchp nfit mac_hid btusb btrtl btbcm btintel bluetooth parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse e1000 vmwgfx drm_kms_helper syscopyarea sysfillrect mptspi scsi_transport_spi ahci mptscsih libahci mptbase sysimgblt fb_sys_fops
[ 2678.729367]  ttm drm pata_acpi fjes
[ 2678.729405] CPU: 0 PID: 4594 Comm: doio Not tainted 4.10.0-nova #3
[ 2678.729466] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[ 2678.729588] task: ffff9532f39a0000 task.stack: ffffa7fec4e4c000
[ 2678.729648] RIP: 0010:nova_vma_close+0x1a2/0x260 [nova]
[ 2678.729782] RSP: 0018:ffffa7fec4e4fe40 EFLAGS: 00010246
[ 2678.729854] RAX: dead000000000200 RBX: ffff9531719bef40 RCX: 0000000000736f6d
[ 2678.730038] RDX: dead000000000100 RSI: ffff9532f981fa40 RDI: ffff9531719bef40
[ 2678.730106] RBP: ffffa7fec4e4fea0 R08: 000000000001fa40 R09: ffffffffc05de770
[ 2678.730170] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[ 2678.730258] R13: ffff9532c12b2000 R14: ffff95315e36e870 R15: ffff95315e36e7c8
[ 2678.730323] FS:  00007f2035219700(0000) GS:ffff9532f9800000(0000) knlGS:0000000000000000
[ 2678.730395] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2678.730463] CR2: 00007f2033f3b000 CR3: 00000000b1b3f000 CR4: 00000000003406f0
[ 2678.730570] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 2678.730635] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 2678.730700] Call Trace:
[ 2678.730753]  remove_vma+0x32/0x70
[ 2678.730786]  do_munmap+0x2b2/0x460
[ 2678.730835]  SyS_munmap+0x50/0x70
[ 2678.730871]  entry_SYSCALL_64_fastpath+0x1e/0xad
[ 2678.730915] RIP: 0033:0x7f2034b30c77
[ 2678.730948] RSP: 002b:00007ffc164cc1d8 EFLAGS: 00000202 ORIG_RAX: 000000000000000b
[ 2678.731033] RAX: ffffffffffffffda RBX: 000055e1deaaa520 RCX: 00007f2034b30c77
[ 2678.731099] RDX: 0000000000000004 RSI: 0000000000c35000 RDI: 00007f2033df9000
[ 2678.731182] RBP: 00007ffc164cc790 R08: 0000000000000007 R09: 000055e1deaa9f89

Nova crashes on fsx tests in ltp

The first/only test in runtests/fsx

fsx-linux export TCbin=$LTPROOT/testcases/bin;fsxtest02 10000

Similar to #29.

Causes a crash outside of nova. e.g.:

[  104.359924] BUG: unable to handle kernel NULL pointer dereference at 0000000000000008
[  104.362476] IP: get_page_from_freelist+0x1e6/0xb20
[  104.363930] PGD 0

[  104.365014] Oops: 0002 [#1] SMP
[  104.366116] Modules linked in: nova(OE) libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc vmw_balloon aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm uvcvideo videobuf2_vmalloc dax_pmem videobuf2_memops snd_seq_midi snd_seq_midi_event snd_rawmidi snd_seq joydev nd_pmem vmw_vsock_vmci_transport vsock dax nd_btt videobuf2_v4l2 input_leds videobuf2_core serio_raw videodev snd_timer btusb snd_seq_device btrtl media btbcm btintel bluetooth snd soundcore i2c_piix4 vmw_vmci shpchp nfit mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid vmwgfx psmouse drm_kms_helper mptspi scsi_transport_spi mptscsih ahci libahci e1000 syscopyarea sysfillrect sysimgblt fb_sys_fops
[  104.386730]  ttm mptbase drm pata_acpi fjes
[  104.388078] CPU: 0 PID: 24009 Comm: fsx-linux Tainted: G           OE   4.10.0-nova #8
[  104.390645] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  104.393732] task: ffff8def8b7c8000 task.stack: ffffb5871027c000
[  104.395471] RIP: 0010:get_page_from_freelist+0x1e6/0xb20
[  104.397034] RSP: 0018:ffffb5871027fad8 EFLAGS: 00010002
[  104.398573] RAX: 0000000000000000 RBX: ffffb5871027fbb0 RCX: ffff8defb961d070
[  104.400654] RDX: 0000000000000000 RSI: 0000000000060c20 RDI: 000000000000420a
[  104.402720] RBP: ffffb5871027fb98 R08: ffffe97d42b4dfa0 R09: 0000000000000010
[  104.404800] R10: 0000000000000000 R11: 0000000000000002 R12: 0000000000000000
[  104.406826] R13: ffff8defbffd5090 R14: ffff8defbffd3680 R15: ffffe97d42b4df80
[  104.408959] FS:  00007f83168de700(0000) GS:ffff8defb9600000(0000) knlGS:0000000000000000
[  104.411270] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  104.413163] CR2: 0000000000000008 CR3: 00000000544ca000 CR4: 00000000003406f0
[  104.415463] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  104.417438] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  104.419428] Call Trace:
[  104.420142]  __alloc_pages_nodemask+0xff/0x260
[  104.421388]  alloc_pages_current+0x95/0x140
[  104.422613]  __get_free_pages+0xe/0x30
[  104.423690]  tlb_next_batch.isra.41+0x37/0x70
[  104.424971]  unmap_page_range+0x6d9/0x8b0
[  104.426108]  unmap_single_vma+0x7d/0xe0
[  104.427235]  unmap_vmas+0x51/0xa0
[  104.428209]  unmap_region+0xbd/0x130
[  104.429224]  do_munmap+0x273/0x460
[  104.430314]  SyS_munmap+0x50/0x70
[  104.431299]  entry_SYSCALL_64_fastpath+0x1e/0xad
[  104.432658] RIP: 0033:0x7f8316413c77
[  104.433709] RSP: 002b:00007ffc854957f8 EFLAGS: 00000297 ORIG_RAX: 000000000000000b
[  104.435876] RAX: ffffffffffffffda RBX: 0000000000007ac1 RCX: 00007f8316413c77
[  104.437890] RDX: 0000000000000000 RSI: 000000000000a02a RDI: 00007f83168ef000
[  104.439863] RBP: 000000000001102a R08: 0000000000000006 R09: 00007f831686d03a
[  104.441828] R10: 0000000000000001 R11: 0000000000000297 R12: 00007ffc85495820
[  104.443797] R13: 00007f83168ef000 R14: 0000000000000006 R15: 0000000000009569
[  104.445765] Code: 49 39 c0 0f 84 88 06 00 00 45 85 ff 0f 84 52 03 00 00 49 83 c1 01 49 c1 e1 04 4e 8b 44 09 08 4d 8d 78 e0 49 8b 47 28 49 8b 57 20 <48> 89 42 08 48 89 10 48 b8 00 01 00 00 00 00 ad de 49 89 47 20
[  104.451172] RIP: get_page_from_freelist+0x1e6/0xb20 RSP: ffffb5871027fad8
[  104.453072] CR2: 0000000000000008
[  104.454029] ---[ end trace 8043131bb0ae64dd ]---
[  104.775567] BUG: unable to handle kernel NULL pointer dereference at 0000000000000008
[  104.777081] IP: get_page_from_freelist+0x1e6/0xb20
[  104.777988] PGD 0

[  104.778761] Oops: 0002 [#2] SMP
[  104.779377] Modules linked in: nova(OE) libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc vmw_balloon aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm uvcvideo videobuf2_vmalloc dax_pmem videobuf2_memops snd_seq_midi snd_seq_midi_event snd_rawmidi snd_seq joydev nd_pmem vmw_vsock_vmci_transport vsock dax nd_btt videobuf2_v4l2 input_leds videobuf2_core serio_raw videodev snd_timer btusb snd_seq_device btrtl media btbcm btintel bluetooth snd soundcore i2c_piix4 vmw_vmci shpchp nfit mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid vmwgfx psmouse drm_kms_helper mptspi scsi_transport_spi mptscsih ahci libahci e1000 syscopyarea sysfillrect sysimgblt fb_sys_fops
[  104.795482]  ttm mptbase drm pata_acpi fjes
[  104.796600] CPU: 1 PID: 5 Comm: kworker/u256:0 Tainted: G      D    OE   4.10.0-nova #8
[  104.798473] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  104.800968] Workqueue: events_freezable_power_ disk_events_workfn
[  104.802438] task: ffff8defb8bfda00 task.stack: ffffb5870066c000
[  104.803816] RIP: 0010:get_page_from_freelist+0x1e6/0xb20
[  104.805053] RSP: 0018:ffffb5870066fa80 EFLAGS: 00010002
[  104.806266] RAX: 0000000000000000 RBX: ffffb5870066fb58 RCX: ffff8defb965d070
[  104.807921] RDX: 0000000000000000 RSI: 0000000000060c20 RDI: 000000000000420a
[  104.809554] RBP: ffffb5870066fb40 R08: ffffe97d42b4dea0 R09: 0000000000000010
[  104.811190] R10: 0000000000000000 R11: 0000000000000002 R12: 0000000000000000
[  104.812861] R13: ffff8defbffd5090 R14: ffff8defbffd3680 R15: ffffe97d42b4de80
[  104.814625] FS:  0000000000000000(0000) GS:ffff8defb9640000(0000) knlGS:0000000000000000
[  104.816539] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  104.817947] CR2: 0000000000000008 CR3: 00000002112ba000 CR4: 00000000003406e0
[  104.819856] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  104.821596] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  104.823308] Call Trace:
[  104.823929]  ? alloc_request_struct+0x19/0x20
[  104.824985]  __alloc_pages_nodemask+0xff/0x260
[  104.826078]  alloc_pages_current+0x95/0x140
[  104.827099]  bio_copy_kern+0xce/0x200
[  104.827993]  blk_rq_map_kern+0xa1/0x130
[  104.829057]  __scsi_execute.isra.23+0x77/0x1d0
[  104.830144]  scsi_execute_req_flags+0x9c/0x110
[  104.831232]  sr_check_events+0xc4/0x2e0
[  104.832182]  cdrom_check_events+0x18/0x30
[  104.833174]  sr_block_check_events+0x2a/0x30
[  104.834280]  disk_check_events+0x5f/0x140
[  104.835408]  disk_events_workfn+0x16/0x20
[  104.836384]  process_one_work+0x1fc/0x490
[  104.837366]  worker_thread+0x4b/0x500
[  104.838264]  kthread+0x101/0x140
[  104.839075]  ? process_one_work+0x490/0x490
[  104.840113]  ? kthread_create_on_node+0x60/0x60
[  104.841214]  ret_from_fork+0x2c/0x40
[  104.842097] Code: 49 39 c0 0f 84 88 06 00 00 45 85 ff 0f 84 52 03 00 00 49 83 c1 01 49 c1 e1 04 4e 8b 44 09 08 4d 8d 78 e0 49 8b 47 28 49 8b 57 20 <48> 89 42 08 48 89 10 48 b8 00 01 00 00 00 00 ad de 49 89 47 20
[  104.846691] RIP: get_page_from_freelist+0x1e6/0xb20 RSP: ffffb5870066fa80
[  104.848321] CR2: 0000000000000008
[  104.849150] ---[ end trace 8043131bb0ae64de ]---

Support changing the number CPUs

Nova uses a bunch of per-cpu data structures, some of which are persistent. It should be possible to move nova from between machines with different numbers of CPUs.

Combine metadata_csum with replica_metadata

They need to have the same value, so we should just have one flag.

LTP rwtest04 crashes the kernel

similar to #41

XFSTests generic/422: stat returns a larger block count than it should

The specific failure in in generic/422 is that du -h returns 72k for files that should be 64k.
df uses stat to compute the file size, so it would seem that this behavior from stat is the cause.

I thought possible source of bug is inode.c:1201, but that's not it. inode->i_blocks is too high. Run script below and watch dmesg.

# yes | head -100 | sudo su -c 'cat > /tmp/foo1'
# /usr/bin/stat  /tmp/foo1
  File: /tmp/foo1
  Size: 200       	Blocks: 8          IO Block: 4096   regular file
Device: 801h/2049d	Inode: 288         Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2017-06-30 06:46:32.972508176 +0000
Modify: 2017-06-30 06:46:32.972508176 +0000
Change: 2017-06-30 06:46:32.972508176 +0000
 Birth: -

#  yes | head -100 | sudo su -c 'cat > /mnt/ramdisk/foo1 '
#  /usr/bin/stat  /mnt/ramdisk/foo1
  File: /mnt/ramdisk/foo1
  Size: 200       	Blocks: 7992       IO Block: 4096   regular file
Device: 10301h/66305d	Inode: 43          Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2017-06-30 06:39:55.256860931 +0000
Modify: 2017-06-30 06:45:21.000000000 +0000
Change: 2017-06-30 06:45:21.000000000 +0000
 Birth: -

Useful script:

for i in /tmp/foo /mnt/ramdisk/foo; do 
    sudo dd if=/dev/zero of=$i bs=1k count=1 >/dev/null 2>/dev/null;    
    du $i;
done

4	/tmp/foo
316	/mnt/ramdisk/foo

XFSTests generic/003: atime not implemented properly

NOVA should implement the relatime default.

NOVA crashes on first LTP test

Running the first test in the nova set of ltp tests crashes nova.

gf01 growfiles -W gf01 -b -e 1 -u -i 0 -L 20 -w -C 1 -l -I r -T 10 -f glseek20 -S 2 -d $TMPDIR

The Oops or BUG occurs at different places in the kernel, none of them in nova code itself. Maybe memory corruption?

To recreate, install NOVA-ltp, mount NOVA on /mnt/ramdisk then

sudo /opt/ltp/runltp -f nova-fail -d /mnt/ramdisk

Output from console

[  361.135861] Oops: 0002 [#1] SMP
[  361.136745] Modules linked in: nova(OE) libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc snd_ens1371 gameport snd_ac97_codec aesni_intel ac97_bus vmw_balloon aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf dax_pmem snd_pcm snd_seq_midi snd_seq_midi_event snd_rawmidi btusb btrtl btbcm snd_seq btintel uvcvideo videobuf2_vmalloc videobuf2_memops bluetooth dax videobuf2_v4l2 input_leds videobuf2_core snd_timer nd_pmem snd_seq_device nd_btt videodev media joydev serio_raw snd soundcore vmw_vsock_vmci_transport vsock i2c_piix4 shpchp vmw_vmci nfit mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid mptspi vmwgfx scsi_transport_spi mptscsih drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops e1000 ttm psmouse drm ahci
[  361.158373]  libahci mptbase pata_acpi fjes
[  361.159598] CPU: 3 PID: 2862 Comm: runltp Tainted: G           OE   4.10.0-nova #8
[  361.161859] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  361.164876] task: ffff8d49314f5a00 task.stack: ffff986ec30c8000
[  361.166525] RIP: 0010:get_page_from_freelist+0x1e6/0xb20
[  361.167983] RSP: 0018:ffff986ec30cbbb8 EFLAGS: 00010002
[  361.169389] RAX: ffff8d49396dd080 RBX: ffff986ec30cbc90 RCX: ffff8d49396dd070
[  361.171237] RDX: 0000000000000000 RSI: 00000000000a6c42 RDI: 000000000000420a
[  361.173076] RBP: ffff986ec30cbc78 R08: ffffcd03029cd6a0 R09: 0000000000000010
[  361.174926] R10: 0000000000000000 R11: 0000000000000002 R12: 0000000000000000
[  361.176677] R13: ffff8d493ffd5090 R14: ffff8d493ffd3680 R15: ffffcd03029cd680
[  361.178374] FS:  00007fb77a68e700(0000) GS:ffff8d49396c0000(0000) knlGS:0000000000000000
[  361.180407] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  361.181805] CR2: 0000000000000008 CR3: 00000000b55c9000 CR4: 00000000003406e0
[  361.183616] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  361.185430] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  361.187227] Call Trace:
[  361.187911]  ? x2apic_send_IPI+0x27/0x30
[  361.189348]  __alloc_pages_nodemask+0xff/0x260
[  361.190592]  alloc_pages_current+0x95/0x140
[  361.191678]  __vmalloc_node_range+0x164/0x280
[  361.192819]  ? _do_fork+0xd7/0x390
[  361.193690]  copy_process.part.36+0x609/0x1c40
[  361.194807]  ? _do_fork+0xd7/0x390
[  361.195647]  ? apparmor_file_alloc_security+0x23/0x40
[  361.196906]  ? security_file_alloc+0x33/0x50
[  361.197946]  _do_fork+0xd7/0x390
[  361.198752]  SyS_clone+0x19/0x20
[  361.199546]  do_syscall_64+0x5b/0xc0
[  361.200438]  entry_SYSCALL64_slow_path+0x25/0x25
[  361.201533] RIP: 0033:0x7fb77a18e40a
[  361.202374] RSP: 002b:00007ffc2b9b45d0 EFLAGS: 00000246 ORIG_RAX: 0000000000000038
[  361.204136] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fb77a18e40a
[  361.205761] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000001200011
[  361.207490] RBP: 00007ffc2b9b4600 R08: 0000000000000000 R09: 00007fb77a68e700
[  361.209129] R10: 00007fb77a68e9d0 R11: 0000000000000246 R12: 0000000000000b2e
[  361.210742] R13: 000055c26920ca90 R14: 0000000000000000 R15: 00007ffc2b9b4660
[  361.212349] Code: 49 39 c0 0f 84 88 06 00 00 45 85 ff 0f 84 52 03 00 00 49 83 c1 01 49 c1 e1 04 4e 8b 44 09 08 4d 8d 78 e0 49 8b 47 28 49 8b 57 20 <48> 89 42 08 48 89 10 48 b8 00 01 00 00 00 00 ad de 49 89 47 20
[  361.216847] RIP: get_page_from_freelist+0x1e6/0xb20 RSP: ffff986ec30cbbb8
[  361.218417] CR2: 0000000000000008
[  361.219608] ---[ end trace 994798b5544901a7 ]---
[  361.221470] BUG: unable to handle kernel NULL pointer dereference at 0000000000000008
[  361.223265] IP: get_page_from_freelist+0x1e6/0xb20
[  361.224406] PGD 0
[  361.224407]
[  361.225487] Oops: 0002 [#2] SMP
[  361.226457] Modules linked in: nova(OE) libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc snd_ens1371 gameport snd_ac97_codec aesni_intel ac97_bus vmw_balloon aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf dax_pmem snd_pcm snd_seq_midi snd_seq_midi_event snd_rawmidi btusb btrtl btbcm snd_seq btintel uvcvideo videobuf2_vmalloc videobuf2_memops bluetooth dax videobuf2_v4l2 input_leds videobuf2_core snd_timer nd_pmem snd_seq_device nd_btt videodev media joydev serio_raw snd soundcore vmw_vsock_vmci_transport vsock i2c_piix4 shpchp vmw_vmci nfit mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid mptspi vmwgfx scsi_transport_spi mptscsih drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops e1000 ttm psmouse drm ahci
[  361.243821]  libahci mptbase pata_acpi fjes
[  361.244828] CPU: 3 PID: 2862 Comm: runltp Tainted: G      D    OE   4.10.0-nova #8
[  361.246616] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  361.249306] task: ffff8d49314f5a00 task.stack: ffff986ec30c8000
[  361.251078] RIP: 0010:get_page_from_freelist+0x1e6/0xb20
[  361.252598] RSP: 0018:ffff986ec30cbae8 EFLAGS: 00010002
[  361.254272] RAX: ffff8d49396dd080 RBX: ffff986ec30cbbc0 RCX: ffff8d49396dd070
[  361.256347] RDX: 0000000000000000 RSI: 00000000000a6c42 RDI: 000000000000420a
[  361.258069] RBP: ffff986ec30cbba8 R08: ffffcd03029cd6a0 R09: 0000000000000010
[  361.259922] R10: 0000000000000000 R11: 0000000000000002 R12: 0000000000000000
[  361.261820] R13: ffff8d493ffd5090 R14: ffff8d493ffd3680 R15: ffffcd03029cd680
[  361.263430] FS:  00007fb77a68e700(0000) GS:ffff8d49396c0000(0000) knlGS:0000000000000000
[  361.265255] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  361.266579] CR2: 0000000000000008 CR3: 00000000b55c9000 CR4: 00000000003406e0
[  361.268247] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  361.269881] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  361.271498] Call Trace:
[  361.272089]  ? page_fault+0x28/0x30
[  361.272932]  __alloc_pages_nodemask+0xff/0x260
[  361.273977]  alloc_pages_current+0x95/0x140
[  361.274956]  __get_free_pages+0xe/0x30
[  361.275839]  tlb_next_batch.isra.41+0x37/0x70
[  361.276860]  unmap_page_range+0x6d9/0x8b0
[  361.277779]  unmap_single_vma+0x7d/0xe0
[  361.278696]  unmap_vmas+0x51/0xa0
[  361.279471]  exit_mmap+0xa7/0x170
[  361.280269]  mmput+0x57/0x130
[  361.280954]  do_exit+0x273/0xb00
[  361.281725]  rewind_stack_do_exit+0x17/0x20
[  361.282786] RIP: 0033:0x7fb77a18e40a
[  361.283895] RSP: 002b:00007ffc2b9b45d0 EFLAGS: 00000246 ORIG_RAX: 0000000000000038
[  361.285764] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fb77a18e40a
[  361.287667] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000001200011
[  361.289369] RBP: 00007ffc2b9b4600 R08: 0000000000000000 R09: 00007fb77a68e700
[  361.291007] R10: 00007fb77a68e9d0 R11: 0000000000000246 R12: 0000000000000b2e
[  361.292618] R13: 000055c26920ca90 R14: 0000000000000000 R15: 00007ffc2b9b4660
[  361.294246] Code: 49 39 c0 0f 84 88 06 00 00 45 85 ff 0f 84 52 03 00 00 49 83 c1 01 49 c1 e1 04 4e 8b 44 09 08 4d 8d 78 e0 49 8b 47 28 49 8b 57 20 <48> 89 42 08 48 89 10 48 b8 00 01 00 00 00 00 ad de 49 89 47 20
[  361.298588] RIP: get_page_from_freelist+0x1e6/0xb20 RSP: ffff986ec30cbae8
[  361.300170] CR2: 0000000000000008
[  361.300937] ---[ end trace 994798b5544901a8 ]---
[  361.302001] Fixing recursive fault but reboot is needed!

Another example

[  261.596440] nova: init_nova_fs: 2 cpus online
[  261.596442] nova: Arch new instructions support: CLWB NO
[  261.596447] nova: Data structure size: inode 120, log_page 4096, file_write_entry 64, dir_entry(max) 304, setattr_entry 56, link_change_entry 40
[  262.618753] nova: nova_get_nvmm_info: dev pmem0, phys_addr 0x100000000, virt_addr ffff9af0c0000000, size 2147483648
[  262.618754] nova: measure timing 0, metadata checksum 0, inplace metadata update 0, inplace update 0, wprotect 0, mmap Cow 1, data checksum 0, data parity 0, DRAM checksum 0
[  262.618883] nova: Start NOVA snapshot cleaner thread.
[  262.618885] nova: creating an empty nova of size 2147483648
[  262.618914] nova: Running snapshot cleaner thread
[  262.635086] nova: NOVA initialization finish
[  262.635146] nova: Current epoch id: 0
[  262.656014] nova: nova_get_nvmm_info: dev pmem1, phys_addr 0x180000000, virt_addr ffff9af140000000, size 2147483648
[  262.656015] nova: measure timing 0, metadata checksum 0, inplace metadata update 0, inplace update 0, wprotect 0, mmap Cow 1, data checksum 0, data parity 0, DRAM checksum 0
[  262.656145] nova: Start NOVA snapshot cleaner thread.
[  262.656147] nova: creating an empty nova of size 2147483648
[  262.656176] nova: Running snapshot cleaner thread
[  262.672761] nova: NOVA initialization finish
[  262.672769] nova: Current epoch id: 0




















[  296.956204] BUG: unable to handle kernel NULL pointer dereference at 0000000000000008
[  296.956340] IP: get_page_from_freelist+0x1e6/0xb20
[  296.956417] PGD 0

[  296.956479] Oops: 0002 [#1] SMP
[  296.956531] Modules linked in: nova libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc vmw_balloon aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm joydev input_leds nd_pmem dax_pmem dax nd_btt snd_seq_midi serio_raw snd_seq_midi_event snd_rawmidi snd_seq snd_timer snd_seq_device uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core videodev snd btusb btrtl btbcm btintel media bluetooth soundcore nfit vmw_vsock_vmci_transport vsock shpchp i2c_piix4 vmw_vmci mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse vmwgfx drm_kms_helper syscopyarea sysfillrect mptspi ahci libahci e1000 scsi_transport_spi mptscsih mptbase sysimgblt fb_sys_fops
[  296.957644]  ttm drm pata_acpi fjes
[  296.957692] CPU: 1 PID: 3029 Comm: losetup Not tainted 4.10.0-nova #3
[  296.957773] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  296.957904] task: ffff9af1c672ad00 task.stack: ffffbc83449d8000
[  296.957980] RIP: 0010:get_page_from_freelist+0x1e6/0xb20
[  296.958047] RSP: 0018:ffffbc83449dbaa8 EFLAGS: 00010002
[  296.958117] RAX: ffff9af1f985d080 RBX: ffffbc83449dbb80 RCX: ffff9af1f985d070
[  296.958206] RDX: 0000000000000000 RSI: 00000000000a7b7f RDI: 0000000000004203
[  296.958295] RBP: ffffbc83449dbb68 R08: fffff84d42c0ce20 R09: 0000000000000010
[  296.958384] R10: 0000000000000000 R11: 0000000000000002 R12: 0000000000000000
[  296.958474] R13: ffff9af2003d5090 R14: ffff9af2003d3680 R15: fffff84d42c0ce00
[  296.958563] FS:  0000000000000000(0000) GS:ffff9af1f9840000(0000) knlGS:0000000000000000
[  296.958664] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  296.958737] CR2: 0000000000000008 CR3: 00000000b021d000 CR4: 00000000003406e0
[  296.958868] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  296.958957] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  296.959046] Call Trace:
[  296.959083]  ? check_preempt_wakeup+0x192/0x230
[  296.959142]  __alloc_pages_nodemask+0xff/0x260
[  296.959200]  alloc_pages_current+0x95/0x140
[  296.959255]  __get_free_pages+0xe/0x30
[  296.959304]  tlb_next_batch.isra.41+0x37/0x70
[  296.959360]  unmap_page_range+0x6d9/0x8b0
[  296.959412]  unmap_single_vma+0x7d/0xe0
[  296.959462]  unmap_vmas+0x51/0xa0
[  296.959506]  exit_mmap+0xa7/0x170
[  296.959550]  mmput+0x57/0x130
[  296.959590]  do_exit+0x273/0xb00
[  296.959633]  ? __do_page_fault+0x2ab/0x520
[  296.959686]  do_group_exit+0x43/0xb0
[  296.959733]  SyS_exit_group+0x14/0x20
[  296.959781]  entry_SYSCALL_64_fastpath+0x1e/0xad
[  296.959841] RIP: 0033:0x7f23b67b8738
[  296.959887] RSP: 002b:00007ffd96722ef8 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
[  296.959982] RAX: ffffffffffffffda RBX: 00007f23b6efe4c8 RCX: 00007f23b67b8738
[  296.960071] RDX: 0000000000000000 RSI: 000000000000003c RDI: 0000000000000000
[  296.960161] RBP: 00007ffd96722ef0 R08: 00000000000000e7 R09: ffffffffffffff90
[  296.960250] R10: 0000000000000004 R11: 0000000000000246 R12: 00007f23b6cd8810
[  296.960339] R13: 0000000000000002 R14: 0000000000000000 R15: 00007ffd96722e20
[  296.960429] Code: 49 39 c0 0f 84 88 06 00 00 45 85 ff 0f 84 52 03 00 00 49 83 c1 01 49 c1 e1 04 4e 8b 44 09 08 4d 8d 78 e0 49 8b 47 28 49 8b 57 20 <48> 89 42 08 48 89 10 48 b8 00 01 00 00 00 00 ad de 49 89 47 20
[  296.960679] RIP: get_page_from_freelist+0x1e6/0xb20 RSP: ffffbc83449dbaa8
[  296.960764] CR2: 0000000000000008
[  296.960808] ---[ end trace 54a5ec9d6d58a560 ]---
[  296.960867] Fixing recursive fault but reboot is needed!
[  297.903658] BUG: unable to handle kernel NULL pointer dereference at 0000000000000008
[  297.903854] IP: get_page_from_freelist+0x1e6/0xb20
[  297.903966] PGD 0

[  297.904057] Oops: 0002 [#2] SMP
[  297.904170] Modules linked in: nova libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc vmw_balloon aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm joydev input_leds nd_pmem dax_pmem dax nd_btt snd_seq_midi serio_raw snd_seq_midi_event snd_rawmidi snd_seq snd_timer snd_seq_device uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core videodev snd btusb btrtl btbcm btintel media bluetooth soundcore nfit vmw_vsock_vmci_transport vsock shpchp i2c_piix4 vmw_vmci mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse vmwgfx drm_kms_helper syscopyarea sysfillrect mptspi ahci libahci e1000 scsi_transport_spi mptscsih mptbase sysimgblt fb_sys_fops
[  297.905284]  ttm drm pata_acpi fjes
[  297.905344] CPU: 1 PID: 249 Comm: kworker/u256:28 Tainted: G      D         4.10.0-nova #3
[  297.905473] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  297.905642] Workqueue: events_freezable_power_ disk_events_workfn
[  297.905738] task: ffff9af1f2042d00 task.stack: ffffbc83433c4000
[  297.905834] RIP: 0010:get_page_from_freelist+0x1e6/0xb20
[  297.905918] RSP: 0018:ffffbc83433c7a80 EFLAGS: 00010002
[  297.906001] RAX: ffff9af1f985d080 RBX: ffffbc83433c7b58 RCX: ffff9af1f985d070
[  297.906113] RDX: 0000000000000000 RSI: 00000000000a7b67 RDI: 0000000000004203
[  297.906225] RBP: ffffbc83433c7b40 R08: fffff84d42c0ce20 R09: 0000000000000010
[  297.906337] R10: 0000000000000000 R11: 0000000000000002 R12: 0000000000000000
[  297.906471] R13: ffff9af2003d5090 R14: ffff9af2003d3680 R15: fffff84d42c0ce00
[  297.906560] FS:  0000000000000000(0000) GS:ffff9af1f9840000(0000) knlGS:0000000000000000
[  297.906660] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  297.906732] CR2: 0000000000000008 CR3: 0000000213f5f000 CR4: 00000000003406e0
[  297.906861] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  297.906950] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  297.907038] Call Trace:
[  297.907077]  ? alloc_request_struct+0x19/0x20
[  297.907134]  __alloc_pages_nodemask+0xff/0x260
[  297.907192]  alloc_pages_current+0x95/0x140
[  297.907246]  bio_copy_kern+0xce/0x200
[  297.907294]  blk_rq_map_kern+0xa1/0x130
[  297.907345]  __scsi_execute.isra.23+0x77/0x1d0
[  297.907402]  scsi_execute_req_flags+0x9c/0x110
[  297.907460]  sr_check_events+0xc4/0x2e0
[  297.907511]  cdrom_check_events+0x18/0x30
[  297.907563]  sr_block_check_events+0x2a/0x30
[  297.907619]  disk_check_events+0x5f/0x140
[  297.907671]  disk_events_workfn+0x16/0x20
[  297.907723]  process_one_work+0x1fc/0x490
[  297.907775]  worker_thread+0x4b/0x500
[  297.907823]  kthread+0x101/0x140
[  297.907866]  ? process_one_work+0x490/0x490
[  297.907920]  ? kthread_create_on_node+0x60/0x60
[  297.907978]  ret_from_fork+0x2c/0x40
[  297.908025] Code: 49 39 c0 0f 84 88 06 00 00 45 85 ff 0f 84 52 03 00 00 49 83 c1 01 49 c1 e1 04 4e 8b 44 09 08 4d 8d 78 e0 49 8b 47 28 49 8b 57 20 <48> 89 42 08 48 89 10 48 b8 00 01 00 00 00 00 ad de 49 89 47 20
[  297.908275] RIP: get_page_from_freelist+0x1e6/0xb20 RSP: ffffbc83433c7a80
[  297.908360] CR2: 0000000000000008
[  297.908405] ---[ end trace 54a5ec9d6d58a561 ]---
[  302.537292] ------------[ cut here ]------------
[  302.537408] kernel BUG at mm/slub.c:3873!
[  302.537504] invalid opcode: 0000 [#3] SMP
[  302.537599] Modules linked in: nova libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc vmw_balloon aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm joydev input_leds nd_pmem dax_pmem dax nd_btt snd_seq_midi serio_raw snd_seq_midi_event snd_rawmidi snd_seq snd_timer snd_seq_device uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core videodev snd btusb btrtl btbcm btintel media bluetooth soundcore nfit vmw_vsock_vmci_transport vsock shpchp i2c_piix4 vmw_vmci mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse vmwgfx drm_kms_helper syscopyarea sysfillrect mptspi ahci libahci e1000 scsi_transport_spi mptscsih mptbase sysimgblt fb_sys_fops
[  302.538770]  ttm drm pata_acpi fjes
[  302.538831] CPU: 1 PID: 543 Comm: vmtoolsd Tainted: G      D         4.10.0-nova #3
[  302.538951] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  302.539117] task: ffff9af1f22b1680 task.stack: ffffbc8343d68000
[  302.539213] RIP: 0010:kfree+0x11c/0x160
[  302.539275] RSP: 0018:ffffbc8343d6bdc8 EFLAGS: 00010246
[  302.539359] RAX: 0000000000000000 RBX: ffff9af07031aa80 RCX: 0000000000081c02
[  302.539471] RDX: 0000000000000000 RSI: ffff9af1f985c680 RDI: 0000650fc0000000
[  302.539583] RBP: ffffbc8343d6bde0 R08: 000000000001c680 R09: ffffffffa49d1753
[  302.539694] R10: fffff84d42c0c680 R11: ffff9af07468a710 R12: ffff9af1f7e4e500
[  302.539806] R13: ffffffffa4a67b81 R14: ffff9af1f84ca120 R15: ffff9aeff6dd2e40
[  302.539943] FS:  00007fc7fe80f1c0(0000) GS:ffff9af1f9840000(0000) knlGS:0000000000000000
[  302.540074] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  302.540149] CR2: 0000000000000008 CR3: 00000002375c2000 CR4: 00000000003406e0
[  302.540293] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  302.540383] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  302.540472] Call Trace:
[  302.540508]  seq_release+0x21/0x30
[  302.540553]  close_pdeo+0x52/0x100
[  302.540598]  proc_reg_release+0x6b/0x70
[  302.540649]  __fput+0xe7/0x220
[  302.540689]  ____fput+0xe/0x10
[  302.540731]  task_work_run+0x80/0xa0
[  302.540778]  exit_to_usermode_loop+0x9b/0xa0
[  302.540833]  syscall_return_slowpath+0x59/0x60
[  302.540892]  entry_SYSCALL_64_fastpath+0xab/0xad
[  302.540952] RIP: 0033:0x7fc7fd68cf5b
[  302.540998] RSP: 002b:00007ffdb71ed978 EFLAGS: 00000206 ORIG_RAX: 0000000000000003
[  302.541093] RAX: 0000000000000000 RBX: 000055bf27d8a410 RCX: 00007fc7fd68cf5b
[  302.541182] RDX: 00007fc7fd9d08c0 RSI: 0000000000000001 RDI: 0000000000000009
[  302.541271] RBP: 00007fc7fd9d1400 R08: 00007fc7fe80f1c0 R09: 0000000000000001
[  302.541361] R10: 00007fc7fe80f1c0 R11: 0000000000000206 R12: 0000000000000000
[  302.541450] R13: 00007ffdb71ed9d4 R14: 00007fc7fe3e15ba R15: 00007ffdb71eda21
[  302.541539] Code: 08 49 83 c4 18 48 89 da 4c 89 ee ff d0 49 8b 04 24 48 85 c0 75 e6 e9 0e ff ff ff 49 8b 02 f6 c4 80 75 0a 49 8b 42 20 a8 01 75 02 <0f> 0b 49 8b 02 31 f6 f6 c4 80 74 04 41 8b 72 6c 4c 89 d7 e8 8c
[  302.541791] RIP: kfree+0x11c/0x160 RSP: ffffbc8343d6bdc8
[  302.541956] ---[ end trace 54a5ec9d6d58a562 ]---
[  302.542048] BUG: unable to handle kernel NULL pointer dereference at 0000000000000008
[  302.542151] IP: get_page_from_freelist+0x1e6/0xb20
[  302.542212] PGD 0

[  302.542261] Oops: 0002 [#4] SMP
[  302.542302] Modules linked in: nova libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc vmw_balloon aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm joydev input_leds nd_pmem dax_pmem dax nd_btt snd_seq_midi serio_raw snd_seq_midi_event snd_rawmidi snd_seq snd_timer snd_seq_device uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core videodev snd btusb btrtl btbcm btintel media bluetooth soundcore nfit vmw_vsock_vmci_transport vsock shpchp i2c_piix4 vmw_vmci mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse vmwgfx drm_kms_helper syscopyarea sysfillrect mptspi ahci libahci e1000 scsi_transport_spi mptscsih mptbase sysimgblt fb_sys_fops
[  302.543185]  ttm drm pata_acpi fjes
[  302.543233] CPU: 1 PID: 543 Comm: vmtoolsd Tainted: G      D         4.10.0-nova #3
[  302.543328] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  302.543476] task: ffff9af1f22b1680 task.stack: ffffbc8343d68000
[  302.543568] RIP: 0010:get_page_from_freelist+0x1e6/0xb20
[  302.543630] RSP: 0018:ffffbc8343d6bae8 EFLAGS: 00010002
[  302.543691] RAX: ffff9af1f985d080 RBX: ffffbc8343d6bbc0 RCX: ffff9af1f985d070
[  302.543774] RDX: 0000000000000000 RSI: 00000000000a7b67 RDI: 0000000000004203
[  302.543856] RBP: ffffbc8343d6bba8 R08: fffff84d42c0ce20 R09: 0000000000000010
[  302.543938] R10: 0000000000000000 R11: 0000000000000002 R12: 0000000000000000
[  302.544021] R13: ffff9af2003d5090 R14: ffff9af2003d3680 R15: fffff84d42c0ce00
[  302.544105] FS:  0000000000000000(0000) GS:ffff9af1f9840000(0000) knlGS:0000000000000000
[  302.544198] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  302.544265] CR2: 0000000000000008 CR3: 00000002375c2000 CR4: 00000000003406e0
[  302.544351] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  302.544433] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  302.544515] Call Trace:
[  302.544548]  ? vprintk_default+0x29/0x50
[  302.544596]  __alloc_pages_nodemask+0xff/0x260
[  302.544649]  alloc_pages_current+0x95/0x140
[  302.544700]  __get_free_pages+0xe/0x30
[  302.544745]  tlb_next_batch.isra.41+0x37/0x70
[  302.544797]  unmap_page_range+0x6d9/0x8b0
[  302.544845]  unmap_single_vma+0x7d/0xe0
[  302.544891]  unmap_vmas+0x51/0xa0
[  302.544932]  exit_mmap+0xa7/0x170
[  302.544973]  mmput+0x57/0x130
[  302.545009]  do_exit+0x273/0xb00
[  302.545049]  ? exit_to_usermode_loop+0x9b/0xa0
[  302.545102]  rewind_stack_do_exit+0x17/0x20
[  302.545152] RIP: 0033:0x7fc7fd68cf5b
[  302.545195] RSP: 002b:00007ffdb71ed978 EFLAGS: 00000206 ORIG_RAX: 0000000000000003
[  302.545282] RAX: 0000000000000000 RBX: 000055bf27d8a410 RCX: 00007fc7fd68cf5b
[  302.545365] RDX: 00007fc7fd9d08c0 RSI: 0000000000000001 RDI: 0000000000000009
[  302.545447] RBP: 00007fc7fd9d1400 R08: 00007fc7fe80f1c0 R09: 0000000000000001
[  302.545529] R10: 00007fc7fe80f1c0 R11: 0000000000000206 R12: 0000000000000000
[  302.545612] R13: 00007ffdb71ed9d4 R14: 00007fc7fe3e15ba R15: 00007ffdb71eda21
[  302.545694] Code: 49 39 c0 0f 84 88 06 00 00 45 85 ff 0f 84 52 03 00 00 49 83 c1 01 49 c1 e1 04 4e 8b 44 09 08 4d 8d 78 e0 49 8b 47 28 49 8b 57 20 <48> 89 42 08 48 89 10 48 b8 00 01 00 00 00 00 ad de 49 89 47 20
[  302.545925] RIP: get_page_from_freelist+0x1e6/0xb20 RSP: ffffbc8343d6bae8
[  302.546004] CR2: 0000000000000008
[  302.546044] ---[ end trace 54a5ec9d6d58a563 ]---
[  302.546098] Fixing recursive fault but reboot is needed!
[  302.895729] BUG: unable to handle kernel NULL pointer dereference at 0000000000000008
[  302.895837] IP: get_page_from_freelist+0x1e6/0xb20
[  302.895898] PGD 0

[  302.895947] Oops: 0002 [#5] SMP
[  302.895989] Modules linked in: nova libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc vmw_balloon aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm joydev input_leds nd_pmem dax_pmem dax nd_btt snd_seq_midi serio_raw snd_seq_midi_event snd_rawmidi snd_seq snd_timer snd_seq_device uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core videodev snd btusb btrtl btbcm btintel media bluetooth soundcore nfit vmw_vsock_vmci_transport vsock shpchp i2c_piix4 vmw_vmci mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse vmwgfx drm_kms_helper syscopyarea sysfillrect mptspi ahci libahci e1000 scsi_transport_spi mptscsih mptbase sysimgblt fb_sys_fops
[  302.896873]  ttm drm pata_acpi fjes
[  302.896920] CPU: 1 PID: 564 Comm: NetworkManager Tainted: G      D         4.10.0-nova #3
[  302.897022] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  302.897153] task: ffff9af1f3301680 task.stack: ffffbc83430b4000
[  302.897229] RIP: 0010:get_page_from_freelist+0x1e6/0xb20
[  302.897296] RSP: 0018:ffffbc83430b78e0 EFLAGS: 00010002
[  302.897362] RAX: ffff9af1f985d080 RBX: ffffbc83430b79b8 RCX: ffff9af1f985d070
[  302.897451] RDX: 0000000000000000 RSI: 00000000000a7b67 RDI: 0000000000004203
[  302.897539] RBP: ffffbc83430b79a0 R08: fffff84d42c0ce20 R09: 0000000000000010
[  302.897628] R10: 0000000000000000 R11: 0000000000000002 R12: 0000000000000000
[  302.897716] R13: ffff9af2003d5090 R14: ffff9af2003d3680 R15: fffff84d42c0ce00
[  302.897805] FS:  00007fed42726540(0000) GS:ffff9af1f9840000(0000) knlGS:0000000000000000
[  302.897905] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  302.897977] CR2: 0000000000000008 CR3: 00000002360ab000 CR4: 00000000003406e0
[  302.898069] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  302.898158] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  302.898246] Call Trace:
[  302.898282]  ? dequeue_task_fair+0x5ab/0xaa0
[  302.898338]  __alloc_pages_nodemask+0xff/0x260
[  302.898396]  alloc_pages_current+0x95/0x140
[  302.898450]  __get_free_pages+0xe/0x30
[  302.898498]  __pollwait+0x99/0xe0
[  302.898542]  datagram_poll+0x29/0x100
[  302.898590]  sock_poll+0x7a/0x90
[  302.898632]  do_sys_poll+0x26e/0x550
[  302.898679]  ? __enqueue_entity+0x6c/0x70
[  302.898731]  ? enqueue_entity+0x113/0x640
[  302.898783]  ? check_preempt_wakeup+0x192/0x230
[  302.898841]  ? poll_initwait+0x50/0x50
[  302.898889]  ? poll_select_copy_remaining+0x150/0x150
[  302.898953]  ? poll_select_copy_remaining+0x150/0x150
[  302.899017]  ? poll_select_copy_remaining+0x150/0x150
[  302.899081]  ? poll_select_copy_remaining+0x150/0x150
[  302.899169]  ? poll_select_copy_remaining+0x150/0x150
[  302.899226]  ? poll_select_copy_remaining+0x150/0x150
[  302.899282]  ? poll_select_copy_remaining+0x150/0x150
[  302.899339]  ? poll_select_copy_remaining+0x150/0x150
[  302.899396]  ? poll_select_copy_remaining+0x150/0x150
[  302.899453]  SyS_poll+0x71/0x130
[  302.899493]  entry_SYSCALL_64_fastpath+0x1e/0xad
[  302.899546] RIP: 0033:0x7fed4003ad8d
[  302.899587] RSP: 002b:00007ffea6dedd80 EFLAGS: 00000293 ORIG_RAX: 0000000000000007
[  302.899672] RAX: ffffffffffffffda RBX: 0000000000000001 RCX: 00007fed4003ad8d
[  302.899751] RDX: 00000000000493d0 RSI: 000000000000000a RDI: 000056245a2b8740
[  302.899831] RBP: 000056245a203850 R08: 000000000000000a R09: 0000000000000001
[  302.899910] R10: 000056245a258580 R11: 0000000000000293 R12: 0000000000000000
[  302.899989] R13: 0000000000000000 R14: 0000000000000000 R15: 000056245a21d0b8
[  302.900069] Code: 49 39 c0 0f 84 88 06 00 00 45 85 ff 0f 84 52 03 00 00 49 83 c1 01 49 c1 e1 04 4e 8b 44 09 08 4d 8d 78 e0 49 8b 47 28 49 8b 57 20 <48> 89 42 08 48 89 10 48 b8 00 01 00 00 00 00 ad de 49 89 47 20
[  302.900293] RIP: get_page_from_freelist+0x1e6/0xb20 RSP: ffffbc83430b78e0
[  302.900368] CR2: 0000000000000008
[  302.900408] ---[ end trace 54a5ec9d6d58a564 ]---
[  308.124727] ------------[ cut here ]------------
[  308.124808] kernel BUG at mm/slub.c:3873!
[  308.124876] invalid opcode: 0000 [#6] SMP
[  308.124942] Modules linked in: nova libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc vmw_balloon aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm joydev input_leds nd_pmem dax_pmem dax nd_btt snd_seq_midi serio_raw snd_seq_midi_event snd_rawmidi snd_seq snd_timer snd_seq_device uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core videodev snd btusb btrtl btbcm btintel media bluetooth soundcore nfit vmw_vsock_vmci_transport vsock shpchp i2c_piix4 vmw_vmci mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse vmwgfx drm_kms_helper syscopyarea sysfillrect mptspi ahci libahci e1000 scsi_transport_spi mptscsih mptbase sysimgblt fb_sys_fops
[  308.126064]  ttm drm pata_acpi fjes
[  308.126125] CPU: 1 PID: 330 Comm: systemd-journal Tainted: G      D         4.10.0-nova #3
[  308.126255] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  308.126423] task: ffff9af1f1514380 task.stack: ffffbc8343064000
[  308.126520] RIP: 0010:kfree+0x11c/0x160
[  308.126583] RSP: 0018:ffffbc8343067e30 EFLAGS: 00010246
[  308.126668] RAX: 0000000000000000 RBX: ffff9af07031a980 RCX: 00000000000820a8
[  308.126799] RDX: 0000000000000000 RSI: ffff9af1f985c680 RDI: 0000650fc0000000
[  308.126905] RBP: ffffbc8343067e48 R08: 000000000001c680 R09: ffffffffa49d1753
[  308.126994] R10: fffff84d42c0c680 R11: ffff9af1f6e94510 R12: ffff9af1e92296c0
[  308.127083] R13: ffffffffa4a67bb7 R14: ffff9af1f84ca120 R15: ffff9af1d7485ec0
[  308.127173] FS:  00007f98cfba38c0(0000) GS:ffff9af1f9840000(0000) knlGS:0000000000000000
[  308.127274] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  308.127347] CR2: 0000558a0cd62000 CR3: 00000002315cd000 CR4: 00000000003406e0
[  308.127439] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  308.127528] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  308.127618] Call Trace:
[  308.127653]  single_release+0x27/0x40
[  308.127702]  __fput+0xe7/0x220
[  308.127743]  ____fput+0xe/0x10
[  308.127784]  task_work_run+0x80/0xa0
[  308.127831]  exit_to_usermode_loop+0x9b/0xa0
[  308.127887]  do_syscall_64+0xb3/0xc0
[  308.127934]  entry_SYSCALL64_slow_path+0x25/0x25
[  308.127993] RIP: 0033:0x7f98cedf9f5b
[  308.128040] RSP: 002b:00007fff5f5d8358 EFLAGS: 00000206 ORIG_RAX: 0000000000000003
[  308.128134] RAX: 0000000000000000 RBX: 0000560f2fc7fd30 RCX: 00007f98cedf9f5b
[  308.128224] RDX: 00007f98cf13d8c0 RSI: 0000000000000001 RDI: 0000000000000061
[  308.128313] RBP: 00007f98cf13e400 R08: 00007f98cfba38c0 R09: 0000000000000050
[  308.128402] R10: 00007f98cf141b58 R11: 0000000000000206 R12: 0000000000000000
[  308.128491] R13: 00007fff5f5d8438 R14: 00007fff5f5d8430 R15: 00007f98cf8c06f9
[  308.128580] Code: 08 49 83 c4 18 48 89 da 4c 89 ee ff d0 49 8b 04 24 48 85 c0 75 e6 e9 0e ff ff ff 49 8b 02 f6 c4 80 75 0a 49 8b 42 20 a8 01 75 02 <0f> 0b 49 8b 02 31 f6 f6 c4 80 74 04 41 8b 72 6c 4c 89 d7 e8 8c
[  308.128832] RIP: kfree+0x11c/0x160 RSP: ffffbc8343067e30
[  308.128963] ---[ end trace 54a5ec9d6d58a565 ]---
[  308.129611] BUG: unable to handle kernel NULL pointer dereference at 0000000000000008
[  308.129716] IP: get_page_from_freelist+0x1e6/0xb20
[  308.129784] PGD 0

[  308.129833] Oops: 0002 [#7] SMP
[  308.129880] Modules linked in: nova libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc vmw_balloon aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm joydev input_leds nd_pmem dax_pmem dax nd_btt snd_seq_midi serio_raw snd_seq_midi_event snd_rawmidi snd_seq snd_timer snd_seq_device uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core videodev snd btusb btrtl btbcm btintel media bluetooth soundcore nfit vmw_vsock_vmci_transport vsock shpchp i2c_piix4 vmw_vmci mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse vmwgfx drm_kms_helper syscopyarea sysfillrect mptspi ahci libahci e1000 scsi_transport_spi mptscsih mptbase sysimgblt fb_sys_fops
[  308.130761]  ttm drm pata_acpi fjes
[  308.130806] CPU: 1 PID: 330 Comm: systemd-journal Tainted: G      D         4.10.0-nova #3
[  308.130901] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  308.131024] task: ffff9af1f1514380 task.stack: ffffbc8343064000
[  308.131095] RIP: 0010:get_page_from_freelist+0x1e6/0xb20
[  308.131157] RSP: 0018:ffffbc8343067ae8 EFLAGS: 00010002
[  308.131218] RAX: ffff9af1f985d080 RBX: ffffbc8343067bc0 RCX: ffff9af1f985d070
[  308.131301] RDX: 0000000000000000 RSI: 00000000000a7b67 RDI: 0000000000004203
[  308.131383] RBP: ffffbc8343067ba8 R08: fffff84d42c0ce20 R09: 0000000000000010
[  308.131465] R10: 0000000000000000 R11: 0000000000000002 R12: 0000000000000000
[  308.131547] R13: ffff9af2003d5090 R14: ffff9af2003d3680 R15: fffff84d42c0ce00
[  308.131630] FS:  0000000000000000(0000) GS:ffff9af1f9840000(0000) knlGS:0000000000000000
[  308.131723] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  308.131790] CR2: 0000000000000008 CR3: 00000002315cd000 CR4: 00000000003406e0
[  308.131875] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  308.131957] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  308.132040] Call Trace:
[  308.132072]  ? vprintk_emit+0x312/0x4a0
[  308.132119]  __alloc_pages_nodemask+0xff/0x260
[  308.132173]  alloc_pages_current+0x95/0x140
[  308.132223]  __get_free_pages+0xe/0x30
[  308.132269]  tlb_next_batch.isra.41+0x37/0x70
[  308.132321]  unmap_page_range+0x6d9/0x8b0
[  308.132369]  unmap_single_vma+0x7d/0xe0
[  308.132415]  unmap_vmas+0x51/0xa0
[  308.132456]  exit_mmap+0xa7/0x170
[  308.132497]  mmput+0x57/0x130
[  308.132533]  do_exit+0x273/0xb00
[  308.132573]  ? exit_to_usermode_loop+0x9b/0xa0
[  308.132627]  rewind_stack_do_exit+0x17/0x20
[  308.132677] RIP: 0033:0x7f98cedf9f5b
[  308.132719] RSP: 002b:00007fff5f5d8358 EFLAGS: 00000206 ORIG_RAX: 0000000000000003
[  308.132807] RAX: 0000000000000000 RBX: 0000560f2fc7fd30 RCX: 00007f98cedf9f5b
[  308.132889] RDX: 00007f98cf13d8c0 RSI: 0000000000000001 RDI: 0000000000000061
[  308.132971] RBP: 00007f98cf13e400 R08: 00007f98cfba38c0 R09: 0000000000000050
[  308.133054] R10: 00007f98cf141b58 R11: 0000000000000206 R12: 0000000000000000
[  308.133136] R13: 00007fff5f5d8438 R14: 00007fff5f5d8430 R15: 00007f98cf8c06f9
[  308.133218] Code: 49 39 c0 0f 84 88 06 00 00 45 85 ff 0f 84 52 03 00 00 49 83 c1 01 49 c1 e1 04 4e 8b 44 09 08 4d 8d 78 e0 49 8b 47 28 49 8b 57 20 <48> 89 42 08 48 89 10 48 b8 00 01 00 00 00 00 ad de 49 89 47 20
[  308.133450] RIP: get_page_from_freelist+0x1e6/0xb20 RSP: ffffbc8343067ae8
[  308.133528] CR2: 0000000000000008
[  308.133569] ---[ end trace 54a5ec9d6d58a566 ]---
[  308.133623] Fixing recursive fault but reboot is needed!
[  318.466767] BUG: unable to handle kernel NULL pointer dereference at 0000000000000008
[  318.466864] IP: get_page_from_freelist+0x1e6/0xb20
[  318.466918] PGD 0

[  318.466962] Oops: 0002 [#8] SMP
[  318.466999] Modules linked in: nova libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc vmw_balloon aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm joydev input_leds nd_pmem dax_pmem dax nd_btt snd_seq_midi serio_raw snd_seq_midi_event snd_rawmidi snd_seq snd_timer snd_seq_device uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core videodev snd btusb btrtl btbcm btintel media bluetooth soundcore nfit vmw_vsock_vmci_transport vsock shpchp i2c_piix4 vmw_vmci mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse vmwgfx drm_kms_helper syscopyarea sysfillrect mptspi ahci libahci e1000 scsi_transport_spi mptscsih mptbase sysimgblt fb_sys_fops
[  318.467809]  ttm drm pata_acpi fjes
[  318.467857] CPU: 1 PID: 912 Comm: Xorg Tainted: G      D         4.10.0-nova #3
[  318.467937] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  318.468055] task: ffff9af1e5abc380 task.stack: ffffbc8343fec000
[  318.468123] RIP: 0010:get_page_from_freelist+0x1e6/0xb20
[  318.468183] RSP: 0018:ffffbc8343fef8d0 EFLAGS: 00010002
[  318.468242] RAX: ffff9af1f985d080 RBX: ffffbc8343fef9a8 RCX: ffff9af1f985d070
[  318.468321] RDX: 0000000000000000 RSI: 00000000000a7b67 RDI: 0000000000004203
[  318.468400] RBP: ffffbc8343fef990 R08: fffff84d42c0ce20 R09: 0000000000000010
[  318.468479] R10: 0000000000000000 R11: 0000000000000002 R12: 0000000000000000
[  318.468557] R13: ffff9af2003d5090 R14: ffff9af2003d3680 R15: fffff84d42c0ce00
[  318.468637] FS:  00007fc43d0dda40(0000) GS:ffff9af1f9840000(0000) knlGS:0000000000000000
[  318.468726] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  318.468790] CR2: 0000000000000008 CR3: 0000000236f27000 CR4: 00000000003406e0
[  318.468871] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  318.468950] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  318.469029] Call Trace:
[  318.469061]  __alloc_pages_nodemask+0xff/0x260
[  318.469112]  alloc_pages_current+0x95/0x140
[  318.469165]  ttm_pool_populate+0x2f6/0x4f0 [ttm]
[  318.469221]  ? ida_get_new_above+0x1fc/0x270
[  318.469275]  vmw_ttm_populate+0x34/0xa0 [vmwgfx]
[  318.469330]  ttm_tt_bind+0x2b/0x60 [ttm]
[  318.469377]  ttm_bo_handle_move_mem+0x541/0x5c0 [ttm]
[  318.469436]  ttm_bo_validate+0x145/0x160 [ttm]
[  318.469488]  ? __ww_mutex_lock_interruptible+0x17/0x60
[  318.469548]  ? ttm_prime_handle_to_fd+0x5a/0x210 [ttm]
[  318.469621]  vmw_validate_single_buffer+0x5f/0x80 [vmwgfx]
[  318.469685]  vmw_execbuf_process+0xb88/0x1260 [vmwgfx]
[  318.469746]  vmw_execbuf_ioctl+0xe6/0x1a0 [vmwgfx]
[  318.469803]  vmw_generic_ioctl+0x252/0x290 [vmwgfx]
[  318.469861]  vmw_unlocked_ioctl+0x15/0x20 [vmwgfx]
[  318.469917]  do_vfs_ioctl+0xa3/0x600
[  318.469959]  ? __sys_recvmsg+0x80/0x90
[  318.470003]  SyS_ioctl+0x79/0x90
[  318.470041]  entry_SYSCALL_64_fastpath+0x1e/0xad
[  318.470094] RIP: 0033:0x7fc43aade587
[  318.470135] RSP: 002b:00007ffee87d37a8 EFLAGS: 00003246 ORIG_RAX: 0000000000000010
[  318.470220] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fc43aade587
[  318.470299] RDX: 00007ffee87d3810 RSI: 000000004028644c RDI: 0000000000000010
[  318.470379] RBP: 000056058d8f1860 R08: 000000000000003c R09: 00007ffee87d3878
[  318.470459] R10: 000056058f35e3f0 R11: 0000000000003246 R12: 0000000000000000
[  318.470538] R13: 0000000000000000 R14: 000056058ece1a80 R15: 000056058f1ee560
[  318.470618] Code: 49 39 c0 0f 84 88 06 00 00 45 85 ff 0f 84 52 03 00 00 49 83 c1 01 49 c1 e1 04 4e 8b 44 09 08 4d 8d 78 e0 49 8b 47 28 49 8b 57 20 <48> 89 42 08 48 89 10 48 b8 00 01 00 00 00 00 ad de 49 89 47 20
[  318.470844] RIP: get_page_from_freelist+0x1e6/0xb20 RSP: ffffbc8343fef8d0
[  318.470920] CR2: 0000000000000008
[  318.470961] ---[ end trace 54a5ec9d6d58a567 ]---
[  321.705769] BUG: unable to handle kernel NULL pointer dereference at 0000000000000008
[  321.705904] IP: get_page_from_freelist+0x1e6/0xb20
[  321.705981] PGD 0

[  321.706043] Oops: 0002 [#9] SMP
[  321.706095] Modules linked in: nova libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc vmw_balloon aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm joydev input_leds nd_pmem dax_pmem dax nd_btt snd_seq_midi serio_raw snd_seq_midi_event snd_rawmidi snd_seq snd_timer snd_seq_device uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core videodev snd btusb btrtl btbcm btintel media bluetooth soundcore nfit vmw_vsock_vmci_transport vsock shpchp i2c_piix4 vmw_vmci mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse vmwgfx drm_kms_helper syscopyarea sysfillrect mptspi ahci libahci e1000 scsi_transport_spi mptscsih mptbase sysimgblt fb_sys_fops
[  321.707201]  ttm drm pata_acpi fjes
[  321.707262] CPU: 1 PID: 550 Comm: avahi-daemon Tainted: G      D         4.10.0-nova #3
[  321.707391] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  321.707558] task: ffff9af1f6e98000 task.stack: ffffbc8343e3c000
[  321.707654] RIP: 0010:get_page_from_freelist+0x1e6/0xb20
[  321.707739] RSP: 0018:ffffbc8343e3f908 EFLAGS: 00010002
[  321.707823] RAX: ffff9af1f985d080 RBX: ffffbc8343e3f9e0 RCX: ffff9af1f985d070
[  321.707965] RDX: 0000000000000000 RSI: 00000000000a7b67 RDI: 0000000000004203
[  321.708054] RBP: ffffbc8343e3f9c8 R08: fffff84d42c0ce20 R09: 0000000000000010
[  321.708143] R10: 0000000000000000 R11: 0000000000000002 R12: 0000000000000000
[  321.708233] R13: ffff9af2003d5090 R14: ffff9af2003d3680 R15: fffff84d42c0ce00
[  321.708322] FS:  00007f0a0b4ef880(0000) GS:ffff9af1f9840000(0000) knlGS:0000000000000000
[  321.708423] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  321.708496] CR2: 0000000000000008 CR3: 000000023769e000 CR4: 00000000003406e0
[  321.708588] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  321.708677] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  321.708767] Call Trace:
[  321.708802]  ? set_next_entity+0xc3/0x1b0
[  321.708856]  ? pick_next_task_fair+0x47a/0x4b0
[  321.708914]  ? __switch_to+0x23c/0x520
[  321.708964]  __alloc_pages_nodemask+0xff/0x260
[  321.709022]  alloc_pages_current+0x95/0x140
[  321.709077]  __get_free_pages+0xe/0x30
[  321.709125]  __pollwait+0x99/0xe0
[  321.709169]  pipe_poll+0x31/0x90
[  321.709212]  do_sys_poll+0x26e/0x550
[  321.709260]  ? skb_free_head+0x25/0x30
[  321.709309]  ? skb_release_data+0xfe/0x110
[  321.709363]  ? kfree_skbmem+0x56/0x60
[  321.709410]  ? consume_skb+0x34/0x80
[  321.709458]  ? skb_consume_udp+0x20/0x90
[  321.709508]  ? poll_initwait+0x50/0x50
[  321.709557]  ? poll_select_copy_remaining+0x150/0x150
[  321.709621]  ? poll_select_copy_remaining+0x150/0x150
[  321.709686]  ? poll_select_copy_remaining+0x150/0x150
[  321.709750]  ? poll_select_copy_remaining+0x150/0x150
[  321.709814]  ? poll_select_copy_remaining+0x150/0x150
[  321.709878]  ? poll_select_copy_remaining+0x150/0x150
[  321.709943]  ? poll_select_copy_remaining+0x150/0x150
[  321.710007]  ? poll_select_copy_remaining+0x150/0x150
[  321.710071]  ? poll_select_copy_remaining+0x150/0x150
[  321.710135]  SyS_poll+0x71/0x130
[  321.710178]  entry_SYSCALL_64_fastpath+0x1e/0xad
[  321.710237] RIP: 0033:0x7f0a09fc9d70
[  321.710283] RSP: 002b:00007ffe5090abf8 EFLAGS: 00000246 ORIG_RAX: 0000000000000007
[  321.710379] RAX: ffffffffffffffda RBX: 00007ffe5090a530 RCX: 00007f0a09fc9d70
[  321.710468] RDX: 0000000000000064 RSI: 000000000000000a RDI: 00005614d4146930
[  321.710557] RBP: 00007ffe5090a620 R08: 0000000000000000 R09: 0000000000000000
[  321.710646] R10: 002630cb286ad93f R11: 0000000000000246 R12: 0000000000000002
[  321.710736] R13: 0000000000000001 R14: 000000000000006c R15: 00007ffe5090a5f8
[  321.710825] Code: 49 39 c0 0f 84 88 06 00 00 45 85 ff 0f 84 52 03 00 00 49 83 c1 01 49 c1 e1 04 4e 8b 44 09 08 4d 8d 78 e0 49 8b 47 28 49 8b 57 20 <48> 89 42 08 48 89 10 48 b8 00 01 00 00 00 00 ad de 49 89 47 20
[  321.711076] RIP: get_page_from_freelist+0x1e6/0xb20 RSP: ffffbc8343e3f908
[  321.711161] CR2: 0000000000000008
[  321.711206] ---[ end trace 54a5ec9d6d58a568 ]---
[  321.711496] BUG: unable to handle kernel NULL pointer dereference at 0000000000000008
[  321.711586] IP: get_page_from_freelist+0x1e6/0xb20
[  321.711660] PGD 0

[  321.711703] Oops: 0002 [#10] SMP
[  321.711739] Modules linked in: nova libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc vmw_balloon aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm joydev input_leds nd_pmem dax_pmem dax nd_btt snd_seq_midi serio_raw snd_seq_midi_event snd_rawmidi snd_seq snd_timer snd_seq_device uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core videodev snd btusb btrtl btbcm btintel media bluetooth soundcore nfit vmw_vsock_vmci_transport vsock shpchp i2c_piix4 vmw_vmci mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse vmwgfx drm_kms_helper syscopyarea sysfillrect mptspi ahci libahci e1000 scsi_transport_spi mptscsih mptbase sysimgblt fb_sys_fops
[  321.712519]  ttm drm pata_acpi fjes
[  321.712559] CPU: 1 PID: 550 Comm: avahi-daemon Tainted: G      D         4.10.0-nova #3
[  321.712642] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  321.712751] task: ffff9af1f6e98000 task.stack: ffffbc8343e3c000
[  321.712815] RIP: 0010:get_page_from_freelist+0x1e6/0xb20
[  321.712871] RSP: 0018:ffffbc8343e3fae8 EFLAGS: 00010002
[  321.712926] RAX: ffff9af1f985d080 RBX: ffffbc8343e3fbc0 RCX: ffff9af1f985d070
[  321.713000] RDX: 0000000000000000 RSI: 00000000000a7b67 RDI: 0000000000004203
[  321.713073] RBP: ffffbc8343e3fba8 R08: fffff84d42c0ce20 R09: 0000000000000010
[  321.713147] R10: 0000000000000000 R11: 0000000000000002 R12: 0000000000000000
[  321.713221] R13: ffff9af2003d5090 R14: ffff9af2003d3680 R15: fffff84d42c0ce00
[  321.713295] FS:  00007f0a0b4ef880(0000) GS:ffff9af1f9840000(0000) knlGS:0000000000000000
[  321.713379] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  321.713438] CR2: 0000000000000008 CR3: 000000023769e000 CR4: 00000000003406e0
[  321.713515] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  321.713589] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  321.713662] Call Trace:
[  321.713691]  ? do_sys_poll+0x26e/0x550
[  321.713733]  __alloc_pages_nodemask+0xff/0x260
[  321.713781]  alloc_pages_current+0x95/0x140
[  321.713827]  __get_free_pages+0xe/0x30
[  321.713867]  tlb_next_batch.isra.41+0x37/0x70
[  321.713914]  unmap_page_range+0x6d9/0x8b0
[  321.713957]  unmap_single_vma+0x7d/0xe0
[  321.713998]  unmap_vmas+0x51/0xa0
[  321.714035]  exit_mmap+0xa7/0x170
[  321.714072]  mmput+0x57/0x130
[  321.714104]  do_exit+0x273/0xb00
[  321.714141]  rewind_stack_do_exit+0x17/0x20
[  321.714185] RIP: 0033:0x7f0a09fc9d70
[  321.714224] RSP: 002b:00007ffe5090abf8 EFLAGS: 00000246 ORIG_RAX: 0000000000000007
[  321.714302] RAX: ffffffffffffffda RBX: 00007ffe5090a530 RCX: 00007f0a09fc9d70
[  321.714376] RDX: 0000000000000064 RSI: 000000000000000a RDI: 00005614d4146930
[  321.714450] RBP: 00007ffe5090a620 R08: 0000000000000000 R09: 0000000000000000
[  321.714524] R10: 002630cb286ad93f R11: 0000000000000246 R12: 0000000000000002
[  321.714598] R13: 0000000000000001 R14: 000000000000006c R15: 00007ffe5090a5f8
[  321.714672] Code: 49 39 c0 0f 84 88 06 00 00 45 85 ff 0f 84 52 03 00 00 49 83 c1 01 49 c1 e1 04 4e 8b 44 09 08 4d 8d 78 e0 49 8b 47 28 49 8b 57 20 <48> 89 42 08 48 89 10 48 b8 00 01 00 00 00 00 ad de 49 89 47 20
[  321.714879] RIP: get_page_from_freelist+0x1e6/0xb20 RSP: ffffbc8343e3fae8
[  321.714950] CR2: 0000000000000008
[  321.714986] ---[ end trace 54a5ec9d6d58a569 ]---
[  321.715035] Fixing recursive fault but reboot is needed!
[  353.875650] ------------[ cut here ]------------
[  353.875701] kernel BUG at mm/slub.c:3873!
[  353.875743] invalid opcode: 0000 [#11] SMP
[  353.875785] Modules linked in: nova libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc vmw_balloon aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm joydev input_leds nd_pmem dax_pmem dax nd_btt snd_seq_midi serio_raw snd_seq_midi_event snd_rawmidi snd_seq snd_timer snd_seq_device uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core videodev snd btusb btrtl btbcm btintel media bluetooth soundcore nfit vmw_vsock_vmci_transport vsock shpchp i2c_piix4 vmw_vmci mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse vmwgfx drm_kms_helper syscopyarea sysfillrect mptspi ahci libahci e1000 scsi_transport_spi mptscsih mptbase sysimgblt fb_sys_fops
[  353.876493]  ttm drm pata_acpi fjes
[  353.876531] CPU: 1 PID: 1 Comm: systemd Tainted: G      D         4.10.0-nova #3
[  353.876605] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  353.876710] task: ffff9af1f8fd8000 task.stack: ffffbc8340028000
[  353.876772] RIP: 0010:kfree+0x11c/0x160
[  353.876811] RSP: 0018:ffffbc834002be30 EFLAGS: 00010246
[  353.876864] RAX: 0000000000000000 RBX: ffff9af07031a580 RCX: 0000000000082101
[  353.876935] RDX: 0000000000000000 RSI: ffff9af1f985c680 RDI: 0000650fc0000000
[  353.877006] RBP: ffffbc834002be48 R08: 000000000001c680 R09: ffffffffa49d1753
[  353.877077] R10: fffff84d42c0c680 R11: ffff9af074689910 R12: ffff9af1e9229c40
[  353.877148] R13: ffffffffa4a67bb7 R14: ffff9af1f84ca120 R15: ffff9af1f72195c0
[  353.877219] FS:  00007f2d909b3940(0000) GS:ffff9af1f9840000(0000) knlGS:0000000000000000
[  353.877299] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  353.877357] CR2: 00007fdf57af11f4 CR3: 0000000237441000 CR4: 00000000003406e0
[  353.877430] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  353.877502] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  353.877572] Call Trace:
[  353.877600]  single_release+0x27/0x40
[  353.877639]  __fput+0xe7/0x220
[  353.877671]  ____fput+0xe/0x10
[  353.877704]  task_work_run+0x80/0xa0
[  353.877742]  exit_to_usermode_loop+0x9b/0xa0
[  353.877786]  syscall_return_slowpath+0x59/0x60
[  353.877832]  entry_SYSCALL_64_fastpath+0xab/0xad
[  353.877880] RIP: 0033:0x7f2d8ef1ff5b
[  353.877916] RSP: 002b:00007fff7659a888 EFLAGS: 00000206 ORIG_RAX: 0000000000000003
[  353.877992] RAX: 0000000000000000 RBX: 00005558ab39abe0 RCX: 00007f2d8ef1ff5b
[  353.878063] RDX: 00007f2d8f2638c0 RSI: 0000000000000001 RDI: 000000000000004b
[  353.878133] RBP: 00007f2d8f264400 R08: 00007f2d909b3940 R09: 0000000000000030
[  353.878204] R10: 00007f2d909b3940 R11: 0000000000000206 R12: 0000000000000000
[  353.878275] R13: 00007fff7659a968 R14: 00007fff7659a960 R15: 00007f2d906d46f9
[  353.878346] Code: 08 49 83 c4 18 48 89 da 4c 89 ee ff d0 49 8b 04 24 48 85 c0 75 e6 e9 0e ff ff ff 49 8b 02 f6 c4 80 75 0a 49 8b 42 20 a8 01 75 02 <0f> 0b 49 8b 02 31 f6 f6 c4 80 74 04 41 8b 72 6c 4c 89 d7 e8 8c
[  353.878545] RIP: kfree+0x11c/0x160 RSP: ffffbc834002be30
[  353.878626] ---[ end trace 54a5ec9d6d58a56a ]---
[  353.878695] BUG: unable to handle kernel NULL pointer dereference at 0000000000000008
[  353.878776] IP: get_page_from_freelist+0x1e6/0xb20
[  353.878824] PGD 0

[  353.878863] Oops: 0002 [#12] SMP
[  353.878896] Modules linked in: nova libcrc32c rfcomm bnep coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc vmw_balloon aesni_intel aes_x86_64 crypto_simd cryptd glue_helper intel_rapl_perf snd_ens1371 gameport snd_ac97_codec ac97_bus snd_pcm joydev input_leds nd_pmem dax_pmem dax nd_btt snd_seq_midi serio_raw snd_seq_midi_event snd_rawmidi snd_seq snd_timer snd_seq_device uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core videodev snd btusb btrtl btbcm btintel media bluetooth soundcore nfit vmw_vsock_vmci_transport vsock shpchp i2c_piix4 vmw_vmci mac_hid parport_pc ppdev lp parport ip_tables x_tables autofs4 hid_generic usbhid hid psmouse vmwgfx drm_kms_helper syscopyarea sysfillrect mptspi ahci libahci e1000 scsi_transport_spi mptscsih mptbase sysimgblt fb_sys_fops
[  353.879606]  ttm drm pata_acpi fjes
[  353.879644] CPU: 1 PID: 1 Comm: systemd Tainted: G      D         4.10.0-nova #3
[  353.879718] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/02/2015
[  353.879824] task: ffff9af1f8fd8000 task.stack: ffffbc8340028000
[  353.879885] RIP: 0010:get_page_from_freelist+0x1e6/0xb20
[  353.879939] RSP: 0018:ffffbc834002bae8 EFLAGS: 00010002
[  353.879992] RAX: ffff9af1f985d080 RBX: ffffbc834002bbc0 RCX: ffff9af1f985d070
[  353.880063] RDX: 0000000000000000 RSI: 00000000000a7b48 RDI: 0000000000004203
[  353.880135] RBP: ffffbc834002bba8 R08: fffff84d42c0ce20 R09: 0000000000000010
[  353.880206] R10: 0000000000000000 R11: 0000000000000002 R12: 0000000000000000
[  353.880277] R13: ffff9af2003d5090 R14: ffff9af2003d3680 R15: fffff84d42c0ce00
[  353.880349] FS:  0000000000000000(0000) GS:ffff9af1f9840000(0000) knlGS:0000000000000000
[  353.880430] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  353.880488] CR2: 0000000000000008 CR3: 0000000237441000 CR4: 00000000003406e0
[  353.880561] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  353.880633] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  353.880704] Call Trace:
[  353.880732]  ? vprintk_emit+0x312/0x4a0
[  353.880773]  __alloc_pages_nodemask+0xff/0x260
[  353.880820]  alloc_pages_current+0x95/0x140
[  353.880863]  __get_free_pages+0xe/0x30
[  353.880903]  tlb_next_batch.isra.41+0x37/0x70
[  353.880948]  unmap_page_range+0x6d9/0x8b0
[  353.880990]  unmap_single_vma+0x7d/0xe0
[  353.881030]  unmap_vmas+0x51/0xa0
[  353.881065]  exit_mmap+0xa7/0x170
[  353.881101]  mmput+0x57/0x130
[  353.881132]  do_exit+0x273/0xb00
[  353.881167]  ? exit_to_usermode_loop+0x9b/0xa0
[  353.881213]  rewind_stack_do_exit+0x17/0x20
[  353.881256] RIP: 0033:0x7f2d8ef1ff5b
[  353.881293] RSP: 002b:00007fff7659a888 EFLAGS: 00000206 ORIG_RAX: 0000000000000003
[  353.881369] RAX: 0000000000000000 RBX: 00005558ab39abe0 RCX: 00007f2d8ef1ff5b
[  353.881440] RDX: 00007f2d8f2638c0 RSI: 0000000000000001 RDI: 000000000000004b
[  353.881511] RBP: 00007f2d8f264400 R08: 00007f2d909b3940 R09: 0000000000000030
[  353.881583] R10: 00007f2d909b3940 R11: 0000000000000206 R12: 0000000000000000
[  353.881654] R13: 00007fff7659a968 R14: 00007fff7659a960 R15: 00007f2d906d46f9
[  353.881726] Code: 49 39 c0 0f 84 88 06 00 00 45 85 ff 0f 84 52 03 00 00 49 83 c1 01 49 c1 e1 04 4e 8b 44 09 08 4d 8d 78 e0 49 8b 47 28 49 8b 57 20 <48> 89 42 08 48 89 10 48 b8 00 01 00 00 00 00 ad de 49 89 47 20
[  353.881927] RIP: get_page_from_freelist+0x1e6/0xb20 RSP: ffffbc834002bae8
[  353.881995] CR2: 0000000000000008
[  353.882039] ---[ end trace 54a5ec9d6d58a56b ]---
[  353.882086] Fixing recursive fault but reboot is needed!

XFStests generic/080: mtime and ctime not updated for dax mmap access

mtime and ctime are not updated in response to mmap() updates.

It's clear that they should be updated. If not, then programs like make will fail if rules use mmap to modify files.

Interesting article discussing the issue of mtime/ctime on mmap files.

https://lwn.net/Articles/564120/

It's not quite clear if the approach described got upstreamed or not.