Crash on FreeBSD/ZFS creating sparse ~/.cache/rpcs3/rpcs3_vm

[jbeich]

Quick summary

Crash on RPCS3 start.

Details

Regressed by 126141c. RPCS3 bogusly assumes ZFS doesn't support sparse files and aborts.

$ rm -rf ~/.config/rpcs3 ~/.cache/rpcs3
$ QT_QPA_PLATFORM=xcb rpcs3
Debugger: 0
RPCS3: Segfault reading location 0000000000000028 at 000000080924151b.
Thread: Main Thread.

Thread id = 0x80be12000.
Segmentation fault

Program received signal SIGTRAP, Trace/breakpoint trap.
thread_ctrl::emergency_exit (reason=...)
    at rpcs3-0.0.16-12301-g309759b72/Utilities/Thread.cpp:2522
2522            if (const auto _this = g_tls_this_thread)
(gdb) backtrace
#0  thread_ctrl::emergency_exit (reason=...)
    at rpcs3-0.0.16-12301-g309759b72/Utilities/Thread.cpp:2522
#1  0x000000000061fb65 in fmt::raw_throw_exception (loc=...,
    fmt=0x43858cb "Failed to initialize sparse file in '%s'\nIt seems this filesystem doesn't support sparse files.\n",
    sup=0x5c24960 <fmt::type_info_v<char const*>>, args=0x7fffffffcf98)
    at rpcs3-0.0.16-12301-g309759b72/Utilities/StrFmt.cpp:335
#2  0x000000000123ed25 in fmt::throw_exception<char, 97ul, char const*>::throw_exception (this=0x7fffffffce70, fmt=...,
    args=@0x7fffffffce68: 0x80bf33300 "/home/foo/.cache/rpcs3/", line=414, col=4,
    file=0x43857c1 "rpcs3-0.0.16-12301-g309759b72/rpcs3/util/vm_native.cpp",
    func=0x46eb9ad "shm") at rpcs3-0.0.16-12301-g309759b72/Utilities/StrFmt.h:286
#3  utils::shm::shm (this=0x947e080 <vm::ps3_::s_hook>, size=34359738368, storage="")
    at rpcs3-0.0.16-12301-g309759b72/rpcs3/util/vm_native.cpp:414
#4  0x00000000010dbc38 in __cxx_global_var_init.117(void) ()
    at rpcs3-0.0.16-12301-g309759b72/rpcs3/Emu/Memory/vm.cpp:1635
#5  0x00000000010dcc3b in _GLOBAL__sub_I_vm.cpp ()
    at rpcs3-0.0.16-12301-g309759b72/rpcs3/Emu/Memory/vm.cpp:594
#6  0x0000000805c2b42d in objlist_call_init (list=<optimized out>, list@entry=0x7fffffffdf88, lockstate=<optimized out>,
    lockstate@entry=0x7fffffffddd0) at /usr/src/libexec/rtld-elf/rtld.c:2889
#7  0x0000000805c29c8a in _rtld (sp=<optimized out>, exit_proc=0x7fffffffe000, objp=0x7fffffffe008)
    at /usr/src/libexec/rtld-elf/rtld.c:841
#8  0x0000000805c273e9 in rtld_start () at /usr/src/libexec/rtld-elf/amd64/rtld_start.S:39
#9  0x0000000000000000 in ?? ()
(gdb) frame 3
#3  utils::shm::shm (this=0x947e080 <vm::ps3_::s_hook>, size=34359738368, storage="")
    at rpcs3-0.0.16-12301-g309759b72/rpcs3/util/vm_native.cpp:414
414                             fmt::throw_exception("Failed to initialize sparse file in '%s'\n"
(gdb) list
409
410                     ensure(::ftruncate(m_file, 0x10000) >= 0);
411                     ensure(::fstat(m_file, &stats) >= 0);
412                     if (stats.st_blocks >= (0x8000 / stats.st_blksize) + 1)
413                     {
414                             fmt::throw_exception("Failed to initialize sparse file in '%s'\n"
415                                     "It seems this filesystem doesn't support sparse files.\n",
416                                     storage.empty() ? fs::get_cache_dir().c_str() : storage.c_str());
417                     }
418
(gdb) print stats
$4 = {
  st_dev = 13352518542533021110,
  st_ino = 812843,
  st_nlink = 1,
  st_mode = 33152,
  st_padding0 = 0,
  st_uid = 1234,
  st_gid = 1234,
  st_padding1 = 0,
  st_rdev = 18446744073709551615,
  st_atim = {
    tv_sec = 1621837105,
    tv_nsec = 326112322
  },
  st_mtim = {
    tv_sec = 1621837105,
    tv_nsec = 326128465
  },
  st_ctim = {
    tv_sec = 1621837105,
    tv_nsec = 326128465
  },
  st_birthtim = {
    tv_sec = 1621837105,
    tv_nsec = 326112322
  },
  st_size = 65536,
  st_blocks = 1,
  st_blksize = 65536,
  st_flags = 2048,
  st_gen = 0,
  st_spare = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
}

$ du -h ~/.cache/rpcs3/rpcs3_vm
512B    /home/foo/.cache/rpcs3/rpcs3_vm
$ du -Ah ~/.cache/rpcs3/rpcs3_vm
 64K    /home/foo/.cache/rpcs3/rpcs3_vm

[Nekotekina]

Need more information. Are files not sparse by default on ZFS? Like if you create zero file, then set its size to X.

[jbeich]

posix_fallocate isn't supported, ftruncate works as usual, explicitly filling depends on filesystem compression:

$ cd ~/.cache

$ truncate -s $((0x800000000)) test_sparse
$ du -h test_sparse
512B    test_sparse
$ du -Ah test_sparse
 32G    test_sparse

$ dd if=/dev/zero of=test_sparse bs=1m count=$((0x800000000 / 1024 / 1024))
$ du -h test_sparse
512B    test_sparse
$ du -Ah test_sparse
 32G    test_sparse

[Nekotekina]

This file is not supposed to have allocated space on disk. What does the test show for 32G part? Reserved disk space?

[jbeich]

On ZFS empty sparse files appear to have st_blocks = 1 regardless of size i.e., file holes are treated as data.

$ truncate -s $((0x800000000)) test_sparse
$ eval $(stat -s test_sparse)
$ zdb -dddddd tank$HOME/.cache $st_ino
Dataset tank/home/foo/.cache [ZPL], ID 8458, cr_txg 1758, 3.35G, 489557 objects, rootbp DVA[0]=<0:50f48a8400:200> DVA[1]=<0:51e75f1000:200> [L0 DMU objset] fletcher4 lz4 unencrypted LE contiguous unique double size=1000L/200P birth=3974171L/3974171P fill=489557 cksum=152276276e:67679222ef9:114eb3e07db1f:217d5abea60f18

    Object  lvl   iblk   dblk  dsize  dnsize  lsize   %full  type
    813056    1   128K   128K      0     512   128K    0.00  ZFS plain file (K=inherit) (Z=inherit=zstd-2)
                                               168   bonus  System attributes
        dnode flags: USERUSED_ACCOUNTED USEROBJUSED_ACCOUNTED
        dnode maxblkid: 0
        path    /test_sparse
        uid     1234
        gid     1234
        atime   Mon May 24 07:58:01 2021
        mtime   Mon May 24 07:58:01 2021
        ctime   Mon May 24 07:58:01 2021
        crtime  Mon May 24 07:58:01 2021
        gen     3974171
        mode    100644
        size    34359738368
        parent  4
        links   1
        pflags  40800000004
Indirect blocks:

[Nekotekina]

Hmm, try #10331
I changed logic for sparse file data detection.

[jbeich]

5db38c0 doesn't help:

$ rm -rf ~/.config/rpcs3 ~/.cache/rpcs3
$ QT_QPA_PLATFORM=xcb rpcs3
Debugger: 0
RPCS3: Segfault reading location 0000000000000028 at 0000000808e4151b.
Thread: Main Thread.

Thread id = 0x80ba12000.
Segmentation fault

Program received signal SIGTRAP, Trace/breakpoint trap.
thread_ctrl::emergency_exit (reason=...) at rpcs3-0.0.16-12306-g5db38c012/Utilities/Thread.cpp:2522
2522            if (const auto _this = g_tls_this_thread)
(gdb) backtrace
#0  thread_ctrl::emergency_exit (reason=...) at rpcs3-0.0.16-12306-g5db38c012/Utilities/Thread.cpp:2522
#1  0x0000000001b6b775 in fmt::raw_throw_exception (loc=...,
    fmt=0x4370a4 "Failed to initialize sparse file in '%s'\nIt seems this filesystem doesn't support sparse files (%d).\n",
    sup=0x549b430 <fmt::type_info_v<char const*, int>>, args=0x7fffffffcf98) at rpcs3-0.0.16-12306-g5db38c012/Utilities/StrFmt.cpp:335
#2  0x0000000001b68683 in fmt::throw_exception<char, 102ul, char const*, int>::throw_exception (this=0x7fffffffce70, fmt=...,
    args=@0x7fffffffce64: 22, args=@0x7fffffffce64: 22, line=442, col=4, file=0x3d7742 "rpcs3-0.0.16-12306-g5db38c012/rpcs3/util/vm_native.cpp",
    func=0x3fd8c0 "shm") at rpcs3-0.0.16-12306-g5db38c012/Utilities/StrFmt.h:286
#3  utils::shm::shm (this=0x8d8e080 <vm::ps3_::s_hook>, size=34359738368, storage="") at rpcs3-0.0.16-12306-g5db38c012/rpcs3/util/vm_native.cpp:442
#4  0x00000000027bd098 in __cxx_global_var_init.117(void) () at rpcs3-0.0.16-12306-g5db38c012/rpcs3/Emu/Memory/vm.cpp:1635
#5  0x00000000027be09b in _GLOBAL__sub_I_vm.cpp () at rpcs3-0.0.16-12306-g5db38c012/rpcs3/Emu/Memory/vm.cpp:594
#6  0x000000080561742d in objlist_call_init (list=<optimized out>, list@entry=0x7fffffffdf98, lockstate=<optimized out>,
    lockstate@entry=0x7fffffffdde0) at /usr/src/libexec/rtld-elf/rtld.c:2889
#7  0x0000000805615c8a in _rtld (sp=<optimized out>, exit_proc=0x7fffffffe010, objp=0x7fffffffe018)
    at /usr/src/libexec/rtld-elf/rtld.c:841
#8  0x00000008056133e9 in rtld_start () at /usr/src/libexec/rtld-elf/amd64/rtld_start.S:39
#9  0x0000000000000000 in ?? ()
(gdb) frame 3
#3  utils::shm::shm (this=0x8d8e080 <vm::ps3_::s_hook>, size=34359738368, storage="") at rpcs3-0.0.16-12306-g5db38c012/rpcs3/util/vm_native.cpp:442
442                             fmt::throw_exception("Failed to initialize sparse file in '%s'\n"
(gdb) list
437
438     #ifdef SEEK_DATA
439                     errno = EINVAL;
440                     if (stats.st_blocks && ::lseek(m_file, 0, SEEK_DATA) ^ stats.st_size && errno != ENXIO)
441                     {
442                             fmt::throw_exception("Failed to initialize sparse file in '%s'\n"
443                                     "It seems this filesystem doesn't support sparse files (%d).\n",
444                                     storage.empty() ? fs::get_cache_dir().c_str() : storage.c_str(), +errno);
445                     }
446     #endif
(gdb) print stats
$1 = {
  st_dev = 13352518542533021110,
  st_ino = 819971,
  st_nlink = 1,
  st_mode = 33152,
  st_padding0 = 0,
  st_uid = 1234,
  st_gid = 1234,
  st_padding1 = 0,
  st_rdev = 18446744073709551615,
  st_atim = {
    tv_sec = 1621870134,
    tv_nsec = 335568540
  },
  st_mtim = {
    tv_sec = 1621870134,
    tv_nsec = 335568540
  },
  st_ctim = {
    tv_sec = 1621870134,
    tv_nsec = 335568540
  },
  st_birthtim = {
    tv_sec = 1621870134,
    tv_nsec = 335568540
  },
  st_size = 65536,
  st_blocks = 1,
  st_blksize = 131072,
  st_flags = 2048,
  st_gen = 0,
  st_spare = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0}
}

[Nekotekina]

Some bug in my logic. Try latest version please.

[jbeich]

Still no good (updated previous reply): ::lseek(m_file, 0, SEEK_DATA) returns 0 but 0 ^ 65536 == 65536.

[Nekotekina]

If whence is SEEK_DATA, the offset is set to the start of the next non-hole file region greater than or equal to the supplied offset.

If it returns 0, it means there is no hole at offset 0, and the file is not sparse. I don't know how can I help with it.

[Nekotekina]

May or should? Because in this particular case, it looks like a bug on BSD side or its ZFS implementation.

[nueidris]

Not FreeBSD specific. I can reproduce the crash on Ubuntu 21.04 running OpenZFS