Performance Debugging with my application on Nanos

[Roopsai507]

I've been testing a server application on both Linux and the Nanos Unikernel. The application binary starts a server and handles requests. On Linux, the total response time for a request is consistently around 100-150ms. However, when running the same application on Nanos, the response time increases significantly to around 1.6-2 seconds.

To investigate this issue, I enabled tracing and ran the application using the following command:

ops pkg load myapp --trace -p 8080 -c config.json --syscall-summary

The trace logs, however, did not provide clear insights into the cause of the latency. Here is a snippet from the logs:

3 thread_wakeup: 3->3 blocked_on thread, RIP=0x13351ce2e
        3 sleep interruptible (on "thread")
        3 thread_wakeup: 3->3 blocked_on thread, RIP=0x13351ce2e
    2 thread_wakeup: 2->2 blocked_on futex, RIP=0x133488117
        3 sleep interruptible (on "thread")
            4 sleep interruptible (on "futex")
            4 thread_wakeup: 4->4 blocked_on futex, RIP=0x1334882c0
    2 sleep interruptible (on "futex")
                    6 sleep interruptible (on "futex")
                    6 thread_wakeup: 6->6 blocked_on futex, RIP=0x1334882c0
        3 thread_wakeup: 3->3 blocked_on thread, RIP=0x13351ce2e
        3 sleep interruptible (on "thread")
                                        11 sleep interruptible (on "futex")
                                        11 thread_wakeup: 11->11 blocked_on futex, RIP=0x1334882c0
                                    10 sleep interruptible (on "futex")
                                    10 thread_wakeup: 10->10 blocked_on futex, RIP=0x1334882c0
                                    10 sleep interruptible (on "futex")
        3 thread_wakeup: 3->3 blocked_on thread, RIP=0x13351ce2e
        3 sleep interruptible (on "thread")
                                    10 thread_wakeup: 10->10 blocked_on futex, RIP=0x1334882c0
                    6 sleep interruptible (on "futex")
                    6 thread_wakeup: 6->6 blocked_on futex, RIP=0x1334882c0

The logs mainly indicate threads being woken up and blocked on futexes, but they do not pinpoint the source of the latency.
How can I effectively debug the increased response time when running on Nanos Unikernel? Are there specific tools or methods that can help identify the root cause of this slowness?

Any insights or suggestions would be greatly appreciated.

[eyberg]

That definitely sounds problematic. ftrace might come in handy here, https://nanovms.com/dev/tutorials/profiling-and-tracing-nanos-unikernel but to start with - how are you comparing these instances? Are they in the cloud? local? Are they both using kvm and are bridged? Can you describe your setup?

Do you have a smaller bit of sample code that is reproducible that you can share?

[Roopsai507]

I am comparing the application performance by running it in a Firecracker microVM using a Debian 12 OS image, as well as running it with OPS, both in qemu and within Firecracker. Both setups showed higher latency compared to running the application directly on the Debian image. All testing is being conducted on my local machine, which is running Ubuntu 20.04.6 (Focal Fossa). Unfortunately, I do not have a sample code snippet available to reproduce the error.

I've created a package under ops/packages/ that includes the application binary and its necessary files(html,css..etc). To execute the application, I use the following command:

ops pkg load myapp --trace -p 8080 -c config.json --syscall-summary

Could you provide steps on how to enable Ftrace for further investigation?

[eyberg]

besides the linked article there is also this, https://github.com/nanovms/nanos/tree/master/tools/trace-utilities , you could also use something like perf, https://nanovms.com/dev/tutorials/measuring-unikernel-cold-boot-time-with-perf

but i kinda feel like they would both be overkill for what you're seeing

I don't know how helpful these tools are going to be for you here - if you're saying a request is taking 1-2 seconds when it should be taking 100-200ms i'd start by timestamping the beginning and end of that request in your request handler and use that as your starting point and then putting in more timestamps halfway, then halfway between that, etc. in between to drill down where it exactly you're seeing an issue

this doesn't sound like it's something nanos related, although it most certainly could be; but it's really hard to know what you're running into without some kind of reproducible code that shows it

i'm not even sure what language you're using here but you could make a simple webserver in that language that either shows this behavior and we can go from there or it doesn't show that behavior and that gives you a clue that there's something inside that request handler that is causing issues; or you could even put a new simple hello route in that app and see if it does the same thing or not

[Roopsai507]

I’m looking to enable ftrace in the ops image. The command I’ve come across is:

make TRACE=ftrace TARGET=my-server run

I've gone through the ftrace tutorial however, I'm unclear on what the TARGET parameter specifically refers to in this context.

Additionally, I need some steps to compile Nanos with my application(consisting of multiple folders/files) and enable ftrace.

[francescolavra]

No, there is currently no support for an strace option that outputs timestamps as -tt does, although it could be added in the future.
The strace output from your Linux invocation looks quite different from the Nanos output (e.g. there are no openat or write syscalls in the Linux output): when capturing the above logs, did you make requests to the same endpoints (the same number of times and in the same sequence) in the two setups?

[Roopsai507]

Yes, in both setups, I made the same single request following with /exit request.

[francescolavra]

I understand now why the two logs are different: by default, the Linux strace tool traces syscalls made from the main thread only, but your application spawns different threads, which presumably make other syscalls.
To have strace follow all threads (which is what the Nanos strace klib does), you have to add the -f command line flag, as in strace -f -c ./my_app.

[Roopsai507]

Yes strace -f -c gave similar output

time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 63.81    0.053644         631        85         8 futex
 20.14    0.016935         604        28           epoll_wait
  4.83    0.004063          18       225           clone3
  4.52    0.003799          31       122           write
  4.42    0.003719          16       221           madvise
  0.57    0.000479           0       897           rt_sigprocmask
  0.40    0.000339           0      1118           gettid
  0.18    0.000150         150         1           fallocate
  0.18    0.000150           0       226           rseq
  0.14    0.000117           0       226           set_robust_list
  0.12    0.000100          33         3           rename
  0.12    0.000098           0       185           mmap
  0.11    0.000093           1        64         1 openat
  0.10    0.000083           0       329           mprotect
  0.09    0.000078           0       155           munmap
  0.05    0.000045           0        52           close
  0.04    0.000033           1        18           getpid
  0.04    0.000032           2        11         2 epoll_ctl
  0.03    0.000023           0        42           read
  0.02    0.000019           0        23           pread64
  0.02    0.000015           0        45           fcntl
  0.02    0.000013           0        14           getdents64
  0.01    0.000009           0        87           uname
  0.01    0.000008           0        14           stat
  0.01    0.000006           0        14           newfstatat
  0.00    0.000004           0         5         5 mkdir
  0.00    0.000004           0         5           fadvise64
  0.00    0.000003           3         1           ftruncate
  0.00    0.000003           0         9           fstatfs
  0.00    0.000003           0         5           readahead
  0.00    0.000002           0         3           access
  0.00    0.000002           0         6           sync_file_range
  0.00    0.000001           1         1           fstat
  0.00    0.000001           0         2           accept
  0.00    0.000001           0         2           recvfrom
  0.00    0.000000           0         1           lseek
  0.00    0.000000           0         6           brk
  0.00    0.000000           0         5           rt_sigaction
  0.00    0.000000           0         3           socket
  0.00    0.000000           0         3           bind
  0.00    0.000000           0         3           listen
  0.00    0.000000           0         3           setsockopt
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         3           fsync
  0.00    0.000000           0         2           fdatasync
  0.00    0.000000           0         1           getcwd
  0.00    0.000000           0         3           unlink
  0.00    0.000000           0         1           readlink
  0.00    0.000000           0         2         1 arch_prctl
  0.00    0.000000           0         1           sched_getaffinity
  0.00    0.000000           0         1           epoll_create
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           prlimit64
  0.00    0.000000           0         1           getrandom
------ ----------- ----------- --------- --------- ----------------
100.00    0.084074                  4286        17 total```

[francescolavra]

OK, so the differences between the 2 syscall summary outputs don't seem significant enough to explain the large difference in latency when handling the request. To get more insights as to what might cause this latency, you could either:

• timestamp in your C code the beginning and end of the request in your request handler, as well as the intermediate steps, as @eyberg suggested earlier, and compare the timestamp sequences you get when running your app natively and in a Nanos VM
• enable full tracing (with strace -f when executing natively, with --trace and the strace klib when executing with Ops), and try to spot significant differences in the 2 outputs; since those outputs are likely going to be pretty verbose (especially the Nanos output which will log many internal kernel events), it may take some time for you to make sense of them

One thing to keep in mind when comparing the 2 setups is that the database files being used by your request handler must be in the same state (cached vs non-cached). So if you want to compare things when files are not cached, you have to drop the caches in your Linux host machine before starting the native Linux app and hitting your endpoint; and if you want to compare things when files are cached, you have to make a first "warm-up" request (which will cache the relevant files), and then compare at the second request.