Add symlink support

[patricoferris]

As part of #510 this PR adds symlink support to Eio_posix and Eio_linux with a stubbed out implementation on Windows. I updated all the uses of Unix.symlink in the FS tests to use Eio.Path.symlink as a test -- definitely worth checking I didn't mess up the arguments I always ln incorrectly!

[talex5]

I think this is backwards. The target of a symlink is its content (a string).

symlink() creates a symbolic link named linkpath which contains the string target.
(from symlink(2))

(the analogy is that ln -s src dst is like cp src dst)

So the API should be:

val symlink : ?exists_ok:bool -> target:string -> _ t -> unit

In particular, we want to limit where you can create a symlink, not what it can point to.

[patricoferris]

Ah! Glad I added the caveat to check that -- thanks ^^" !

I've updated everything, I think, to be correct now. I went for link_to as the name, happy to change that if there are better suggestions:

val symlink : ?exists_ok:bool -> link_to:string -> _ t -> unit

[talex5]

Looks pretty good - thanks!

I pushed some commits to update primitives.h (happens automatically if you have lintcstubs_arity_cmt in your PATH) and I tried to make the signatures more consistent.

Ready to merge once the exists_ok thing is clarified/fixed/removed.

[talex5]

What if it exists with a different target, or isn't a symlink? Also exist vs exists.

(could just drop the exists_ok feature and add it later)

[patricoferris]

Removing exists_ok seems fine to me. However, whilst testing I moved machines and now the linux tests are hanging for me. In particular, it is in test_statx that the second copy_string is causing the process to enter some uninterruptible sleep. The machine is using ZFS... maybe that's making it unhappy... but just thought I'd check to see if it sounds familiar/kernel version problem etc.

let test_statx () =
  let module X = Uring.Statx in
  Eio_main.run @@ fun env ->
  let ( / ) = Eio.Path.( / ) in
  let path = env#cwd / "test3.data" in
  Eio.Path.with_open_out path ~create:(`Exclusive 0o600) @@ fun file ->
  Eio.Flow.copy_string "hello" file;
  Eio.Flow.copy_string "+" file

strace: https://gist.github.com/patricoferris/ace0a69433f299ee4ac94368028bb96b

6.5.0-14-generic #14~22.04.1-Ubuntu

[talex5]

By uninterruptable, you mean Ctrl-C doesn't kill it? The machine has to be rebooted to remove the stuck process? dmesg or /proc/PID/stack might show something.

Does it happen if you just run that single test as a complete program? e.g. this program works for me:

let () =
  Eio_main.run @@ fun env ->
  let ( / ) = Eio.Path.( / ) in
  let path = env#cwd / "test3.data" in
  Eio.Path.with_open_out path ~create:(`Exclusive 0o600) @@ fun file ->
  Eio.Flow.copy_string "hello" file;
  Eio.Flow.copy_string "+" file

If it still hangs without this PR, we should move it to another issue.

@koonwen: can your tools help debug this?

[koonwen]

The tool still needs some work. In the meantime though, I can recommend using bpftrace along with this gist to get a "strace-like" real-time view on the io-uring tracepoints being hit. This might give you a clue on what's happening under the hood.

sudo apt-get install bpftrace
wget https://gist.githubusercontent.com/koonwen/b69867422bc49bd10cf61932e41da362/raw/2f673e1aaf928e1531789c27f8d67869f878cba5/bpftrace_uring_trace.bt
sudo bpftrace bpftrace_uring_trace.bt

[talex5]

@koonwen thanks - that prints a lot of info!

I had a go this morning at getting bpftrace to show probes called by uring workers, and this worked a bit for me:

tracepoint:io_uring:io_uring_create {
  printf("Tracing new uring %d\n", pid);
  @traced[pid] = 1;
}

tracepoint:io_uring:* /@traced[pid]/ { printf("%s\n", probe); }

tracepoint:io_uring:io_uring_task_add /@traced[pid]/ {
  printf("%d adds new task: %p\n", tid, args->ctx);
}

kretprobe:create_io_thread / @traced[pid] / {
  $task = (struct task_struct *) retval;
  printf("%s: %d:%d create_io_thread: %d\n", comm, pid, tid, $task->pid);
  @traced[$task->pid] = 1;
}

kprobe:vfs* / @traced[pid] / {
  printf("%s: %s\n", comm, probe);
}

kprobe:vfs_open / @traced[pid] / {
  printf("%s: open(%s)\n", comm, str(((struct path *)arg0)->dentry->d_name.name));
}

kprobe:__fsnotify_parent / @traced[pid] / {
  $dentry = (struct dentry *) arg0;
  printf("%s: __fsnotify_parent(%s)\n", comm, str($dentry->d_name.name));
}

For me, @patricoferris's test case gives:

Attaching 98 probes...
Tracing new uring 12889
tracepoint:io_uring:io_uring_create
tracepoint:io_uring:io_uring_register
tracepoint:io_uring:io_uring_register
tracepoint:io_uring:io_uring_submit_req
tracepoint:io_uring:io_uring_file_get
tracepoint:io_uring:io_uring_poll_arm
tracepoint:io_uring:io_uring_submit_req
tracepoint:io_uring:io_uring_queue_async_work
main.exe: 12889:12889 create_io_thread: 12900
tracepoint:io_uring:io_uring_cqring_wait
iou-wrk-12889: kprobe:vfs_open
iou-wrk-12889: open(test3.data)
iou-wrk-12889: __fsnotify_parent(test3.data)
iou-wrk-12889: __fsnotify_parent(test3.data)
tracepoint:io_uring:io_uring_complete
tracepoint:io_uring:io_uring_task_work_run
tracepoint:io_uring:io_uring_submit_req
tracepoint:io_uring:io_uring_file_get
tracepoint:io_uring:io_uring_queue_async_work
tracepoint:io_uring:io_uring_cqring_wait
iou-wrk-12889: __fsnotify_parent(test3.data)
tracepoint:io_uring:io_uring_complete
tracepoint:io_uring:io_uring_task_work_run
tracepoint:io_uring:io_uring_submit_req
tracepoint:io_uring:io_uring_file_get
tracepoint:io_uring:io_uring_queue_async_work
tracepoint:io_uring:io_uring_cqring_wait
iou-wrk-12889: __fsnotify_parent(test3.data)
tracepoint:io_uring:io_uring_complete
tracepoint:io_uring:io_uring_task_work_run
main.exe: __fsnotify_parent(test3.data)
tracepoint:io_uring:io_uring_submit_req
tracepoint:io_uring:io_uring_task_add
12889 adds new task: 0xffff90cbe90e7800
tracepoint:io_uring:io_uring_complete
tracepoint:io_uring:io_uring_complete
tracepoint:io_uring:io_uring_task_work_run
main.exe: __fsnotify_parent(main.exe)
main.exe: __fsnotify_parent(ld-linux-x86-64.so.2)
main.exe: __fsnotify_parent(libm.so.6)
main.exe: __fsnotify_parent(libc.so.6)

Some combination of these might help track it down!

[patricoferris]

Quick update that @talex5's trace file gives me:

Attaching 97 probes...
Tracing new uring 1203664
tracepoint:io_uring:io_uring_create
tracepoint:io_uring:io_uring_register
tracepoint:io_uring:io_uring_register
tracepoint:io_uring:io_uring_submit_req
tracepoint:io_uring:io_uring_file_get
tracepoint:io_uring:io_uring_poll_arm
tracepoint:io_uring:io_uring_submit_req
tracepoint:io_uring:io_uring_queue_async_work
test.exe: 1203664:1203664 create_io_thread: 1203665
tracepoint:io_uring:io_uring_cqring_wait
iou-wrk-1203664: kprobe:vfs_open
iou-wrk-1203664: open(test3.data)
tracepoint:io_uring:io_uring_complete
tracepoint:io_uring:io_uring_task_work_run
tracepoint:io_uring:io_uring_submit_req
tracepoint:io_uring:io_uring_file_get
tracepoint:io_uring:io_uring_queue_async_work
tracepoint:io_uring:io_uring_cqring_wait
tracepoint:io_uring:io_uring_complete
tracepoint:io_uring:io_uring_task_work_run
tracepoint:io_uring:io_uring_submit_req
tracepoint:io_uring:io_uring_file_get
tracepoint:io_uring:io_uring_queue_async_work
tracepoint:io_uring:io_uring_cqring_wait

so presumably iou-wrk-12889: __fsnotify_parent(test3.data) is not arriving... or something

[talex5]

OK, I installed Ubuntu 22.04.4 and set up a zfs partition and got the same problem. The Eio tests pass on ext4, but hang on zfs.

test.exe is using 100% CPU (I was trying to run apt at the same time and that was taking ages due to this too):

user@ubuntu:~$ pidstat 1
Linux 5.15.0-102-generic (ubuntu) 	18/04/24 	_x86_64_	(1 CPU)

10:50:36      UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
10:50:37     1000     26476    0.00   97.03    0.00    0.00   97.03     0  test.exe
10:50:37        0     27178    1.98    0.00    0.00  113.86    1.98     0  apt-check

The process itself is just waiting for uring_enter to return:

user@ubuntu:/proc/26476$ sudo cat stack 
[<0>] io_cqring_wait+0x374/0x430
[<0>] __do_sys_io_uring_enter+0x1f6/0x540
[<0>] __x64_sys_io_uring_enter+0x22/0x30
[<0>] do_syscall_64+0x5c/0xc0
[<0>] entry_SYSCALL_64_after_hwframe+0x62/0xcc

The CPU use is coming from a uring worker thread:

user@ubuntu:/proc/26476$ pidstat -t 1
10:51:43      UID      TGID       TID    %usr %system  %guest   %wait    %CPU   CPU  Command
10:51:44     1000     26476         -    0.00   98.00    0.00    0.00   98.00     0  test.exe
10:51:44     1000         -     26477    0.00   99.00    0.00    2.00   99.00     0  |__iou-wrk-26476

The worker is doing various things:

user@ubuntu:/proc/26477$ sudo cat stack 
[<0>] dsl_dir_tempreserve_impl.constprop.0+0x129/0x370 [zfs]
[<0>] dsl_dir_tempreserve_space+0xed/0x150 [zfs]
[<0>] dmu_tx_try_assign+0x266/0x2f0 [zfs]
[<0>] dmu_tx_assign+0x54/0x80 [zfs]
[<0>] zfs_write+0x45c/0xdb0 [zfs]
[<0>] zpl_iter_write+0xe7/0x130 [zfs]
[<0>] io_write+0x109/0x330
[<0>] io_issue_sqe+0x338/0x13f0
[<0>] io_wq_submit_work+0x8d/0xf0
[<0>] io_worker_handle_work+0x100/0x2b0
[<0>] io_wqe_worker+0x2c3/0x320
[<0>] ret_from_fork+0x22/0x30

perf gives some samples:

   - zpl_iter_write                                                                                                             ▒
      - 97.27% zfs_write                                                                                                        ▒
         + 26.55% dmu_tx_assign                                                                                                 ▒
         + 25.26% dmu_tx_commit                                                                                                 ▒
         + 19.62% dmu_write_uio_dbuf                                                                                            ▒
         + 11.91% dmu_tx_hold_write_by_dnode                                                                                    ▒
         + 5.27% dmu_tx_create                                                                                                  ▒
         + 3.45% dmu_tx_hold_sa                                                                                                 ▒
           0.87% zfs_clear_setid_bits_if_necessary                                                                              ▒
           0.59% zfs_id_overblockquota                                                                                          ▒

After rebooting the VM, I tried with 14ae3cf (i.e. without the symlink commits) and that hangs too, so I don't think it needs to block this PR. This is a ZFS (or Linux) bug.

[avsm]

I can reproduce this (only) under a ZFS partition using Linux 6.8 too:

Linux comanche 6.8.0-22-generic #22-Ubuntu SMP PREEMPT_DYNAMIC Thu Apr  4 22:30:32 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux

Works fine on a ext4 partition with the same kernel. We should extract a standalone test case here for reporting upstream.

[talex5]

I've opened ocaml-multicore/ocaml-uring#113 to track the uring bug. I've also removed the exists_ok option, made the example a bit more meaningful, and squashed and rebased. Ready for merge now, I think.