--- title: "Troubleshooting NFS Performance Using strace" slug: "troubleshooting-nfs-performance-using-strace" description: "Troubleshooting NFS Performance Using strace" updated: 2026-10-27T19:37:32Z published: 2026-10-28T19:52:20Z canonical: "docs.vastdata.com/troubleshooting-nfs-performance-using-strace" --- > ## Documentation Index > Fetch the complete documentation index at: https://docs.vastdata.com/llms.txt > Use this file to discover all available pages before exploring further. # Troubleshooting NFS Performance Using strace ## Using strace to Troubleshoot NFS Performance **Summary:** This guide shows how to use `strace` to diagnose NFS-related performance issues, interpret syscall patterns, and identify slow or inefficient I/O. Real-world examples and actionable tips are included. --- ## How strace Works - A Technical Overview ### What is strace? `strace` is a diagnostic tool that intercepts and records system calls made by a process. It sits between your application and the Linux kernel, capturing every request your program makes to the operating system. ### How Does It Work? 1. **Process Attachment via** [**ptrace()**](https://en.wikipedia.org/wiki/Ptrace) ```plaintext Application → [strace intercepts] → Kernel → NFS/Storage ``` - Uses the `ptrace()` system call to attach to a process. - Can attach to running processes (`-p PID`) or start new ones. - Acts like a debugger, pausing the process at each system call. 2. **System Call Interception** - When your app makes a system call (like `read()`, `write()`, `open()`): - Process is paused - strace records the call details - Kernel executes the system call - strace records the result and timing - Process continues - This creates up to a 2x increase in context switches. 3. **Timing Measurement** ```plaintext read(5, "data...", 4096) = 1024 <0.002145>                                 ↑                         Time spent in kernel ``` - The `<0.002145>` shows time spent inside the kernel. - Includes time waiting for the NFS server response. - Critical for identifying slow operations. ### **What Gets Captured?** 1. **System Call Information**: - Call name: `openat`, `read`, `write`, etc. - Arguments: file descriptors, buffers, flags - Return value: success/failure codes - Timing: duration of the call 2. **Process Information**: - PID (Process ID) - Timestamp when call was made - Thread information with `-f` flag ### Why It's Perfect for NFS Debugging NFS operations appear as regular file system calls to applications: ```plaintext Application thinks:     strace sees:           What actually happens: fd = open("file")  →   openat(...) = 3    →   NFS RPC: LOOKUP + OPEN read(fd, buf, 4096) →  read(3,...) = 4096 →   NFS RPC: READ close(fd)          →   close(3) = 0       →   NFS RPC: CLOSE ``` ### Performance Impact - **Overhead**: strace adds 10-100x slowdown to system calls - **Why**: Each syscall requires two context switches - **Best practice**: Use in test environments or briefly in production ### Key strace Options for NFS ```plaintext bash ``` ```plaintext strace -f -T -tt -o trace.out command       │  │  │   └─ Write to file       │  │  └─ Absolute timestamps       │  └─ Show time in syscalls       └─ Follow child processes # Filter specific calls strace -e trace=file     # All file operations strace -e trace=open,read,write,close  # Specific calls ``` ### What the Timing Tells You ```plaintext read(4, "PACK\0\0\0\2\0\69\n", 12) = 12 <0.234538> ``` This 234ms read could indicate: - **Network latency** to NFS server - **Server disk I/O** slowness - **NFS protocol overhead** (authentication, etc.) - **Network congestion** ### Behind the Scenes - NFS + strace When you read a file over NFS: 1. App calls `read()` → strace starts timer 2. Kernel VFS layer receives call 3. NFS client creates RPC request 4. Network round-trip to NFS server 5. Server reads from disk 6. Server sends response 7. Kernel returns data to app → strace stops timer The beauty of strace is it captures the **total** time, including all network and server delays! ### 📋 Quick Example ```plaintext bash ``` ```bash # Fast local disk read read(3, "data", 4096) = 4096 <0.000052>  # 52 microseconds # Slow NFS read read(3, "data", 4096) = 4096 <0.045123>  # 45 milliseconds # Network timeout/retry read(3, "data", 4096) = 4096 <5.234567>  # 5+ seconds! ``` This is why strace is so powerful for NFS troubleshooting - it immediately shows you which operations are slow, without needing to understand the complex NFS protocol underneath ## When to Use strace - Application is reported as “slow,” but NFS/server metrics look healthy. - You need to pinpoint if slowness is due to system calls, file I/O, or NFS/network issues. --- ## Basic strace Usage **Profile a command and get a syscall summary:** ```plaintext strace -f -c  ``` - `-f`: Follows child processes. - `-c`: Outputs a summary of system call statistics. **Example Output:** ```bash % time     seconds  usecs/call     calls    errors syscall ------ ----------- ----------- --------- --------- ----------------  49.69   13.521276     3380319         4           wait4  27.59    7.507152          16    466692     82293 futex  10.31    2.805373           5    507523           pread64   8.58    2.333674           3    735952        31 read   3.03    0.825550           1    414052           write   0.39    0.105212          26      3996      1138 openat   ... 100.00   27.213860          12   2150774     87458 total ``` **What to look for:** - High time in `read`, `write`, or `pread64` may indicate I/O bottlenecks. - High error counts in `openat`, `read`, or `write` could signal permission or NFS issues. - Compare with local filesystem runs to isolate NFS as the bottleneck. --- ## Advanced: Trace Live NFS I/O with Timing **Attach to a running process and see syscall durations:** ```plaintext strace -T -f -e trace=read,write,open,close,stat,fstat,lstat,getdents -p  -T: Shows syscall duration (in seconds). -e trace=...: Limits output to relevant file and I/O syscalls. ``` **Example Output:** ```plaintext [pid 78795] read(5, ..., 7512) = 1370 <0.001357> [pid 78795] write(4, ..., 8192) = 8192 <0.000015> [pid 78795] read(5, ..., 14389) = 14389 <0.022307> ``` --- ## How to Interpret the Output ### What is a "Large" read/write? - The third argument to `read`/`write` is the buffer size (e.g., 8192, 16384). - Typical NFS I/O sizes are 8K or 16K. Much larger sizes (>1MB) are rare unless tuned. - Very small sizes (e.g., 1-100 bytes) in a tight loop may indicate inefficient application I/O. ### What is a "Slow" read/write? - The number in `<...>` at the end of each line is the syscall duration in seconds. - Most healthy NFS reads/writes complete in a few milliseconds (`<0.001>`). - Consistent durations above 50-100ms (`<0.050>` or higher) are worth investigating. - Example of a slightly slow call: ```plaintext   [pid 78795] read(5, ..., 14389) = 14389 <0.022307> ``` - Example of a problematic call (not in your logs, but for reference): ```plaintext   read(5, ..., 16384) = 16384 <0.500000> ``` ### What to Look For | Symptom | What to Look For in Output | What it Means | | --- | --- | --- | | Fast read/write | `<0.000015>` | Normal, healthy I/O | | Occasional 10-20ms call | `<0.022307>` | Slightly slow, but not critical | | Consistent >50ms calls | `<0.050000>` or higher | NFS/network/server may be slow | | Very small I/O | `read(..., 1)` | Inefficient app I/O pattern | --- ## Practical Workflow 1. **Start your workload and capture its PID:** ```plaintext    sh -c 'echo $$; exec ' & ``` 2. **Attach strace to the PID:** ```plaintext    strace -T -f -e trace=read,write,open,close,stat,fstat,lstat,getdents -p  ``` 3. Real Example ```bash [vastdata@MetaSpaceWorker1 pandas]$ sh -c 'echo $$; exec git clone --quiet https://github.com/pandas-dev/pandas.git > /dev/null 2>&1' & [1] 113652 [vastdata@MetaSpaceWorker1 pandas]$ 113652 [vastdata@MetaSpaceWorker1 pandas]$ strace -T -tt -f -e trace=read,write,open,close,stat,fstat,lstat,getdents -p 113652 strace: Process 113652 attached with 2 threads [pid 113656] 22:25:36.052817 read(5,   [pid 113652] 22:25:36.052937 read(6,   [pid 113656] 22:25:36.058008 <... read resumed>"\0243j\363|>\220i\217\272/\223\235M\340m\241\230\313gA\267\367J\361\205'd\361\372\336\235"..., 39598) = 1370 <0.005051> [pid 113656] 22:25:36.058091 read(5, "\277E\223_\260\353M<\31\6\0\262?4c\346\22\210\267\26x\234{\314\363\230gB\240\210\327\322"..., 38228) = 5433 <0.000007> [pid 113656] 22:25:36.058175 read(5, "\357\337@\373&H\377\274\vn?\331\23e1\243\30F\370\327\35X\212q\245*\214\205\231\276\"\237"..., 32795) = 1361 <0.000421> [pid 113656] 22:25:36.058679 read(5, "\231\311\3319\251z\5\225\f\356\f\217\331?9\324k\335x\277\354\n[\304\372\323\357\327M\275>\331"..., 31434) = 1370 <0.000004> [pid 113656] 22:25:36.058756 read(5, "\370o\10\232\353\370/\235I\354\334\370\343\325}j\21\t\341\10( \0w\261\261\354\350\335\334'\342"..., 30064) = 9840 <0.000008> [pid 113656] 22:25:36.058822 read(5, "!u\265\260\316\256\1\276mHa\17W\327V \366\202@EX\205?\323Z\341\2\312\27?\6\253"..., 20224) = 12274 <0.000007> [pid 113656] 22:25:36.058886 read(5, "@F\24\202\372.\10R\277P\37H\267K\277u\300\216sf\234\201`\372\315\4\353\t\266`\37\237"..., 7950) = 5480 <0.000005> [pid 113656] 22:25:36.058943 read(5, "\32H\356\213\210\315.\227\276\310\230\20Z\274Z~v\200[\262\341\377\31\223\376\2251i\223Y\370\307"..., 2470) = 2470 <0.000004> [pid 113656] 22:25:36.059005 write(4, "\322y\376!/\361\4a\257\4\224m\344k\341'\257\220zxy\3\227\7\177\375+\261\313\354e5"..., 65515) = 65515 <0.000016> [pid 113656] 22:25:36.059074 read(5, "401a", 4) = 4 <0.000004> [pid 113656] 22:25:36.059124 read(5, "\1iH\317'w\300\255\10\224\30\325\22JC\362Q\252X\351}\2611\315\227\300\262\0\t\262\211\335"..., 16406) = 11170 <0.000007> [pid 113656] 22:25:36.059181 read(5, "\23\266\234,\35\261\264\31\222\336B\357\245*\222{\315\16g\274\24\7}\377\324\377[\353^\327\20\376"..., 5236) = 1370 <0.003961> [pid 113656] 22:25:36.063249 read(5, "\326B\344\266V\370\347\321Up\317mg\312\3\344]\262\205\372\336m\307\341\227\235\365\315\346\201z\353"..., 3866) = 3866 <0.000006> [pid 113656] 22:25:36.063339 write(4, "iH\317'w\300\255\10\224\30\325\22JC\362Q\252X\351}\2611\315\227\300\262\0\t\262\211\335\37"..., 16405) = 16405 <0.000009> [pid 113656] 22:25:36.063433 read(5, "4005", 4) = 4 <0.000005> [pid 113656] 22:25:36.063512 read(5, "\1F+bwUm\4\321AR\0\346\0230H\341\316\371\301\221\301<\24\205\33\331A\245)|-"..., 16385) = 2933 <0.000005> [pid 113656] 22:25:36.063589 read(5, "\2029\th\361\372\317\22\216K\227\326\356:X;O\334P\312\301\017100644 com"..., 13452) = 1361 <0.005005> [pid 113656] 22:25:36.068703 read(5, "\4\347\4\220U\24\2*\24\301\177\203\216rx\26\363\207\336)+\276\344%\217\342\261i\2\1\24\205"..., 12091) = 12033 <0.000008> [pid 113656] 22:25:36.068793 read(5, "\210\232\204-\363\344\332\322X22\222\322R:\355\\M\341\344\277K\365F|e\241\261v\345\nc"..., 58) = 58 <0.000004> [pid 113656] 22:25:36.068870 write(4, "F+bwUm\4\321AR\0\346\0230H\341\316\371\301\221\301<\24\205\33\331A\245)|-P"..., 16384) = 16384 <0.000007> [pid 113656] 22:25:36.068949 read(5, "4005", 4) = 4 <0.000004> [pid 113656] 22:25:36.069024 read(5, "\1\343\356M\225\260\377eRd\24\237{\206\361\277\326\226\32\v7\227\324\205\24=\351\211\305\221t>"..., 16385) = 5409 <0.000006> [pid 113656] 22:25:36.069115 read(5, "\346~\261\216\24\332\215\314GW\212c\0050\331,\27y\225tr\254e\322D\302,4\233)\364d"..., 10976) = 1370 <0.000234> [pid 113656] 22:25:36.069439 read(5, "(o\0\264\17f\313\rp\337\307\244\212\361\245\254%_\21\330\22\223Z\203\270\200\336\210f\342\332\335"..., 9606) = 5480 <0.000006> [pid 113656] 22:25:36.069503 read(5, "\206\277\234k\202?\376\366\33x\260\376\277\375\237K\34\347e\310\327\213I\362\r!?L\20eU\271"..., 4126) = 4126 <0.000011> [pid 113656] 22:25:36.069563 write(4, "\343\356M\225\260\377eRd\24\237{\206\361\277\326\226\32\v7\227\324\205\24=\351\211\305\221t>\247"..., 16384) = 16384 <0.000007> [pid 113656] 22:25:36.069617 read(5, "4005", 4) = 4 <0.000004> [pid 113656] 22:25:36.069666 read(5, "\1\301\34\0'O\5\351\215\10\203R*\355+\332\2\364\2161\331\256\241\344H0\214n\234\21\260U"..., 16385) = 2664 <0.000005> [pid 113656] 22:25:36.069717 read(5, "s>4j\205X\377N\217Z\364\27A\344Q\24\221Y\210\5\337\257O\355\3530-\203\347\213\216\243"..., 13721) = 1370 <0.006360> [pid 113656] 22:25:36.076177 read(5, "[\27\322\301\245\327l\313\322\332R\343\261\200\243\f4\24\202\220p2\34\356\3\360\360\7F\10\16\347"..., 12351) = 6850 <0.000007> [pid 113656] 22:25:36.076266 read(5, "\226\343\257\241pT\203\303a\0\26\232)V\340+\301\241Te\306a\31Ns\17\242\257\235X0\r"..., 5501) = 1370 <0.000090> [pid 113656] 22:25:36.076444 read(5, "Rh\372\37aqB\270\373\31\311\353\6\211y\17\221\207@\24\16\257_\306\326\341\253m#\243\314\255"..., 4131) = 4131 <0.000005> [pid 113656] 22:25:36.076545 write(4, "\301\34\0'O\5\351\215\10\203R*\355+\332\2\364\2161\331\256\241\344H0\214n\234\21\260U\302"..., 16384) = 16384 <0.000009> [pid 113656] 22:25:36.076628 read(5, "2005", 4) = 4 <0.000004> [pid 113656] 22:25:36.076709 read(5, "\1;h\201\7\16\210p\352\300\252\306\31\272\256\235>\243J<\21U\21\262\333\201\17\217n*~l"..., 8193) = 8193 <0.000007> [pid 113656] 22:25:36.076787 write(4, ";h\201\7\16\210p\352\300\252\306\31\272\256\235>\243J<\21U\21\262\333\201\17\217n*~lI"..., 8192) = 8192 <0.000006> [pid 113656] 22:25:36.076872 read(5, "4005", 4) = 4 <0.000004> [pid 113656] 22:25:36.076938 read(5, "\1\325\311\316h6\322\35\16\231\f\370\257\267\17>\31\350\351Uh\277b-\247\27,\277\210m\360\307"..., 16385) = 16385 <0.000013> [pid 113656] 22:25:36.076999 write(4, "\325\311\316h6\322\35\16\231\f\370\257\267\17>\31\350\351Uh\277b-\247\27,\277\210m\360\307\260"..., 16384) = 16384 <0.000007> [pid 113656] 22:25:36.077058 read(5, "4005", 4) = 4 <0.000004> [pid 113656] 22:25:36.077112 read(5, "\1U\202\tj\201bZ\212\346\272\266\221\257\271\272\242\202\336Qq@.\206\255`\333\345\311\247\374\26"..., 16385) = 16385 <0.000007> [pid 113656] 22:25:36.077166 write(4, "U\202\tj\201bZ\212\346\272\266\221\257\271\272\242\202\336Qq@.\206\255`\333\345\311\247\374\26 "..., 16384) = 16384 <0.000006> [pid 113656] 22:25:36.077221 read(5, "4005", 4) = 4 <0.000004> [pid 113656] 22:25:36.077270 read(5, "\1\344\31]D<;\306\235\342\213^\16\344<9\"\6e\374\275 \35\0\0,\1m\20\252\273\22"..., 16385) = 2922 <0.000005> [pid 113656] 22:25:36.077321 read(5, "\377\28\24H\213u!%*\5]\240\326v\n(lg\260\35@\26A\263K\3\177\1\22\362\27"..., 13463) = 1370 <0.000651> [pid 113656] 22:25:36.078044 read(5, "\v\3546A\36\301\2b\0\234\7\207x \245N2Q\355?\216B\f\320b\374p\244\341l\204\302"..., 12093) = 4110 <0.000006> [pid 113656] 22:25:36.078130 read(5, "\261\34\266\25\234\251\22U{\356\4\361&\214#'\306\255\253\324e\261\36U\301&3\1\177\30\361\340"..., 7983) = 1370 <0.002329> [pid 113656] 22:25:36.080553 read(5, "Y\344\21\340\32\253F\1\246\215\2343\361\262c\325\24\233\231%\346\252E\253f3\257\245bZ\240\331"..., 6613) = 6613 <0.000006> ``` 4. **Watch for:** - Slow read/write calls (duration in `<...>`). - Unusually large or small I/O sizes. - Repeated or failed open/stat calls. --- ## Automating Slow Call Detection You can grep for slow calls in your strace log: ```plaintext grep -E 'read|write' strace.log | awk '{ if ($NF > 0.05) print $0 }' ``` This flags any read/write taking longer than 50ms. --- ## Hints for Field Validation - Simulate NFS slowness (e.g., network delay) and verify that read and write durations increase. - Use the output to identify which files or operations are slow, and correlate with NFS server logs or metrics. - Share strace logs with support if deeper analysis is needed. --- **Questions?** Share your strace output, and we can help interpret it with this tool. ```python #!/usr/bin/env python3 """ An strace analyzer focused on NFS performance insights. """ import re import sys import time from collections import defaultdict from datetime import datetime # Known syscalls to validate parsing KNOWN_SYSCALLS = {    'read', 'write', 'open', 'openat', 'close', 'stat', 'fstat', 'lstat',    'pread64', 'pwrite64', 'fsync', 'fdatasync', 'mkdir', 'rmdir', 'unlink',    'rename', 'getdents', 'getdents64', 'lseek', 'mmap', 'munmap', 'brk',    'rt_sigaction', 'rt_sigprocmask', 'rt_sigreturn', 'ioctl', 'access',    'pipe', 'select', 'poll', 'epoll_wait', 'clone', 'fork', 'vfork',    'execve', 'exit', 'wait4', 'kill', 'fcntl', 'flock', 'futex',    'nanosleep', 'getpid', 'socket', 'connect', 'accept', 'sendto',    'recvfrom', 'shutdown', 'bind', 'listen', 'getsockname', 'getpeername',    'socketpair', 'setsockopt', 'getsockopt', 'pselect6', 'ppoll',    'epoll_create', 'dup', 'dup2', 'pause', 'getitimer', 'alarm',    'setitimer', 'getpgid', 'getppid', 'getpgrp', 'setsid', 'getcwd',    'chdir', 'fchdir', 'chmod', 'fchmod', 'chown', 'fchown', 'umask',    'gettimeofday', 'settimeofday', 'mprotect', 'msync', 'mlock',    'munlock', 'mlockall', 'munlockall', 'mremap', 'madvise', 'shmget',    'shmat', 'shmctl', 'semget', 'semop', 'semctl', 'shmdt', 'msgget',    'msgsnd', 'msgrcv', 'msgctl', 'newfstatat', 'getdents64', 'getcwd',    'readlink', 'sysinfo', 'times', 'getuid', 'getgid', 'setuid',    'setgid', 'geteuid', 'getegid', 'setpgid', 'umask', 'uname',    'statfs', 'fstatfs', 'getpriority', 'setpriority', 'sched_getparam',    'sched_setparam', 'sched_getscheduler', 'sched_setscheduler',    'sched_get_priority_max', 'sched_get_priority_min', 'sched_rr_get_interval',    'recvmsg', 'sendmsg', 'getrlimit', 'setrlimit', 'getrusage',    'getsockopt', 'setsockopt', 'getsockname', 'getpeername', 'sendfile',    'symlink', 'link', 'readlinkat', 'fstatat', 'getxattr', 'lgetxattr',    'fgetxattr', 'listxattr', 'llistxattr', 'flistxattr', 'removexattr',    'lremovexattr', 'fremovexattr', 'setxattr', 'lsetxattr', 'fsetxattr' } def parse_strace_line(line):    """Parse strace line with better validation."""    # Pattern for format: PID TIMESTAMP syscall(args) = result    # Example: 79033 09:20:48.857449 brk(NULL) = 0x562ec57bb000 <0.000004>    timing_pattern = r'^\d+\s+\d+:\d+:\d+\.\d+\s+(\w+)\((.*?)\)\s*=\s*([^<]+?)\s*<(\d+\.\d+)>'    match = re.match(timing_pattern, line.strip())    if match:        syscall = match.group(1)        # Validate it's a real syscall        if syscall not in KNOWN_SYSCALLS:            return None        args = match.group(2)        result = match.group(3).strip()        duration = float(match.group(4))        # Check if it's an error result        is_error = '-1' in result or 'EINVAL' in result or 'ENOENT' in result or 'error' in result.lower()        return {            'syscall': syscall,            'args': args,            'result': result,            'duration': duration,            'is_error': is_error,            'line': line.strip()        }    # Also try pattern for lines that might have [pid XXXX] format    alt_pattern = r'^\[pid\s+\d+\]\s+(\w+)\((.*?)\)\s*=\s*([^<]+?)\s*<(\d+\.\d+)>'    match = re.match(alt_pattern, line.strip())    if match:        syscall = match.group(1)        if syscall not in KNOWN_SYSCALLS:            return None        args = match.group(2)        result = match.group(3).strip()        duration = float(match.group(4))        is_error = '-1' in result or 'EINVAL' in result or 'ENOENT' in result or 'error' in result.lower()        return {            'syscall': syscall,            'args': args,            'result': result,            'duration': duration,            'is_error': is_error,            'line': line.strip()        }    return None def categorize_operations():    """Define operation categories for analysis."""    return {        'File Operations': ['open', 'openat', 'close', 'read', 'write',                           'pread64', 'pwrite64', 'lseek'],        'Directory Operations': ['mkdir', 'rmdir', 'getdents', 'getdents64'],        'Metadata Operations': ['stat', 'fstat', 'lstat', 'newfstatat',                               'chmod', 'chown', 'access'],        'Sync Operations': ['fsync', 'fdatasync', 'sync', 'syncfs'],        'Path Operations': ['unlink', 'rename', 'link', 'symlink'],        'Memory Mapping': ['mmap', 'munmap', 'mremap', 'msync'],        'Process/Thread': ['futex', 'clone', 'wait4', 'exit'],    } def analyze_strace_file(filename):    """Analyze strace file with progress and validation."""    import os    syscall_stats = defaultdict(lambda: {        'count': 0,        'total_time': 0,        'max_time': 0,        'min_time': float('inf'),        'errors': 0    })    slow_calls = []  # Calls over 10ms    error_calls = []  # Failed calls    file_size = os.path.getsize(filename)    bytes_read = 0    lines_processed = 0    calls_found = 0    parse_errors = 0    print(f"Analyzing: {filename}")    print(f"File size: {file_size:,} bytes ({file_size/1024/1024:.2f} MB)")    print("-" * 60)    start_time = time.time()    with open(filename, 'r', buffering=8192*1024) as f:        for line in f:            lines_processed += 1            bytes_read += len(line.encode('utf-8'))            if lines_processed % 10000 == 0:                progress = (bytes_read / file_size) * 100                elapsed = time.time() - start_time                rate = bytes_read / elapsed / 1024 / 1024 if elapsed > 0 else 0                print(f"\rProgress: {progress:5.1f}% | Lines: {lines_processed:,} | "                      f"Valid syscalls: {calls_found:,} | Rate: {rate:.1f} MB/s",                      end='', flush=True)            parsed = parse_strace_line(line)            if parsed:                calls_found += 1                syscall = parsed['syscall']                duration = parsed['duration']                result = parsed['result']                stats = syscall_stats[syscall]                stats['count'] += 1                stats['total_time'] += duration                if duration > stats['max_time']:                    stats['max_time'] = duration                if duration < stats['min_time']:                    stats['min_time'] = duration                # Track errors                if parsed['is_error']:                    stats['errors'] += 1                    if len(error_calls) < 100:  # Keep first 100 errors                        error_calls.append(parsed)                # Track slow calls (>10ms)                if duration > 0.01:                    if len(slow_calls) < 1000:                        slow_calls.append(parsed)                    elif duration > slow_calls[-1]['duration']:                        slow_calls[-1] = parsed                        slow_calls.sort(key=lambda x: x['duration'], reverse=True)            else:                # Line didn't parse - might be continuation or data                if '<' in line and '>' in line and '=' in line:                    parse_errors += 1    analysis_time = time.time() - start_time    print(f"\n\nAnalysis complete in {analysis_time:.2f} seconds")    print(f"Valid syscalls: {calls_found:,} | Parse errors: {parse_errors:,}")    return syscall_stats, slow_calls, error_calls def format_duration(seconds):    """Format duration in human-readable form."""    if seconds >= 1:        return f"{seconds:.3f}s"    elif seconds >= 0.001:        return f"{seconds*1000:.3f}ms"    else:        return f"{seconds*1000000:.1f}µs" def print_performance_summary(syscall_stats):    """Print clear performance summary focused on insights."""    categories = categorize_operations()    print("\n" + "="*80)    print("PERFORMANCE SUMMARY BY OPERATION TYPE")    print("="*80)    total_time = sum(s['total_time'] for s in syscall_stats.values())    total_calls = sum(s['count'] for s in syscall_stats.values())    # Analyze by category    category_stats = {}    for category, ops in categories.items():        cat_time = 0        cat_count = 0        cat_errors = 0        slowest = None        for op in ops:            if op in syscall_stats:                stats = syscall_stats[op]                cat_time += stats['total_time']                cat_count += stats['count']                cat_errors += stats['errors']                if not slowest or stats['max_time'] > slowest[1]:                    slowest = (op, stats['max_time'])        if cat_count > 0:            category_stats[category] = {                'time': cat_time,                'count': cat_count,                'errors': cat_errors,                'slowest': slowest,                'percent': (cat_time / total_time * 100) if total_time > 0 else 0            }    # Sort by time spent    sorted_categories = sorted(category_stats.items(),                              key=lambda x: x[1]['time'],                              reverse=True)    for category, stats in sorted_categories:        print(f"\n{category}:")        print(f"  Total time: {format_duration(stats['time'])} ({stats['percent']:.1f}% of total)")        print(f"  Operations: {stats['count']:,}")        print(f"  Average: {format_duration(stats['time']/stats['count'])}")        if stats['errors'] > 0:            print(f"  Errors: {stats['errors']} ({stats['errors']/stats['count']*100:.1f}%)")        if stats['slowest']:            print(f"  Slowest: {stats['slowest'][0]} took {format_duration(stats['slowest'][1])}") def print_nfs_insights(syscall_stats, slow_calls):    """Print NFS-specific performance insights."""    print("\n" + "="*80)    print("NFS PERFORMANCE INSIGHTS")    print("="*80)    # Key NFS operations    nfs_ops = {        'open/close': ['open', 'openat', 'close'],        'read/write': ['read', 'write', 'pread64', 'pwrite64'],        'metadata': ['stat', 'fstat', 'lstat', 'newfstatat', 'getdents', 'getdents64'],        'sync': ['fsync', 'fdatasync'],        'directory': ['mkdir', 'rmdir', 'unlink', 'rename']    }    print("\nOperation Performance:")    print("-" * 70)    print(f"{'Category':<15} {'Count':>10} {'Total Time':>12} {'Avg Latency':>12} {'Max Latency':>12}")    print("-" * 70)    total_nfs_time = 0    total_nfs_ops = 0    for category, ops in nfs_ops.items():        cat_count = 0        cat_time = 0        cat_max = 0        for op in ops:            if op in syscall_stats:                stats = syscall_stats[op]                cat_count += stats['count']                cat_time += stats['total_time']                cat_max = max(cat_max, stats['max_time'])        if cat_count > 0:            total_nfs_time += cat_time            total_nfs_ops += cat_count            avg_time = cat_time / cat_count            print(f"{category:<15} {cat_count:>10,} {format_duration(cat_time):>12} "                  f"{format_duration(avg_time):>12} {format_duration(cat_max):>12}")    # Performance indicators    print("\n" + "="*80)    print("PERFORMANCE INDICATORS")    print("="*80)    # Calculate metrics    if total_nfs_ops > 0:        avg_latency = total_nfs_time / total_nfs_ops * 1000  # in ms        # Count slow operations        slow_reads = sum(1 for c in slow_calls if c['syscall'] in ['read', 'pread64'])        slow_writes = sum(1 for c in slow_calls if c['syscall'] in ['write', 'pwrite64'])        slow_metadata = sum(1 for c in slow_calls if c['syscall'] in ['stat', 'fstat', 'lstat', 'newfstatat'])        print(f"\n{'Metric':<40} {'Value':>20}")        print("-" * 60)        print(f"{'Average NFS operation latency':<40} {avg_latency:>19.3f}ms")        print(f"{'Total NFS operations':<40} {total_nfs_ops:>20,}")        print(f"{'Total time in NFS operations':<40} {format_duration(total_nfs_time):>20}")        print(f"{'Operations slower than 10ms':<40} {len(slow_calls):>20}")        print(f"{'  - Slow reads':<40} {slow_reads:>20}")        print(f"{'  - Slow writes':<40} {slow_writes:>20}")        print(f"{'  - Slow metadata ops':<40} {slow_metadata:>20}")        # Performance assessment        print("\n" + "="*80)        print("PERFORMANCE ASSESSMENT")        print("="*80)        if avg_latency < 1:            print("✓ EXCELLENT: Average latency under 1ms - NFS is performing very well")        elif avg_latency < 5:            print("✓ GOOD: Average latency under 5ms - NFS performance is acceptable")        elif avg_latency < 10:            print("⚠ WARNING: Average latency 5-10ms - Some performance degradation")        else:            print("✗ POOR: Average latency over 10ms - Significant NFS performance issues")        if slow_reads > 100 or slow_writes > 100:            print("\n⚠ HIGH SLOW OPERATION COUNT:")            if slow_reads > 100:                print(f"  - {slow_reads} slow read operations detected")            if slow_writes > 100:                print(f"  - {slow_writes} slow write operations detected")            print("  Consider investigating network latency or storage performance") def print_slow_operations(slow_calls, limit=10):    """Print slowest operations with context."""    print("\n" + "="*80)    print(f"TOP {limit} SLOWEST OPERATIONS")    print("="*80)    # Filter out wait4 and similar non-NFS operations    nfs_related = ['open', 'openat', 'close', 'read', 'write', 'pread64',                   'pwrite64', 'stat', 'fstat', 'lstat', 'newfstatat',                   'fsync', 'fdatasync', 'mkdir', 'unlink', 'rename',                   'getdents', 'getdents64']    nfs_slow_calls = [c for c in slow_calls if c['syscall'] in nfs_related]    if nfs_slow_calls:        print("\nNFS-Related Slow Operations:")        print("-" * 80)        print(f"{'Duration':>10} {'Syscall':<12} {'Details'}")        print("-" * 80)        for call in nfs_slow_calls[:limit]:            args_preview = call['args'][:50] + '...' if len(call['args']) > 50 else call['args']            print(f"{format_duration(call['duration']):>10} {call['syscall']:<12} {args_preview}")    # Also show non-NFS slow calls for context    other_slow = [c for c in slow_calls if c['syscall'] not in nfs_related][:5]    if other_slow:        print("\nOther Slow Operations (for context):")        print("-" * 80)        for call in other_slow:            print(f"{format_duration(call['duration']):>10} {call['syscall']:<12}") def main():    if len(sys.argv) != 2:        print("Usage: python strace_analyzer_improved.py ")        print("\nGenerate strace output with:")        print("  strace -f -T -tt -o output.txt command")        sys.exit(1)    filename = sys.argv[1]    try:        syscall_stats, slow_calls, error_calls = analyze_strace_file(filename)        # Print comprehensive report        print_performance_summary(syscall_stats)        print_nfs_insights(syscall_stats, slow_calls)        print_slow_operations(slow_calls)        # Print errors if any        if error_calls:            print("\n" + "="*80)            print("FAILED OPERATIONS (First 10)")            print("="*80)            for call in error_calls[:10]:                print(f"{call['syscall']}: {call['args'][:60]}...")    except FileNotFoundError:        print(f"Error: File '{filename}' not found.")        sys.exit(1)    except KeyboardInterrupt:        print("\n\nAnalysis interrupted.")        sys.exit(1) if __name__ == "__main__":    main() ``` Example Output: ```python $ python3 ./strace_analyzer.py git_clone_trace.txt Analyzing: git_clone_trace.txt File size: 420,631,345 bytes (401.15 MB) ------------------------------------------------------------ Progress: 100.0% | Lines: 4,290,000 | Valid syscalls: 577,251 | Rate: 3.0 MB/s Analysis complete in 131.55 seconds Valid syscalls: 577,708 | Parse errors: 1,904,059 ================================================================================ NFS OPERATION PERFORMANCE ================================================================================ Operation Performance: ---------------------------------------------------------------------- Category             Count   Total Time  Avg Latency  Max Latency ---------------------------------------------------------------------- open/close           6,638       5.207s      784.5µs     24.030ms read/write         492,432      31.526s       64.0µs    234.538ms metadata             7,436       3.277s      440.6µs      9.441ms sync                     3     21.175ms      7.058ms     13.304ms directory              311    536.980ms      1.727ms      6.502ms ================================================================================ PERFORMANCE INDICATORS ================================================================================ Metric                                                  Value ------------------------------------------------------------ Average NFS operation latency                          0.080ms Total NFS operations                                  506,820 Total time in NFS operations                          40.568s Operations slower than 10ms                               149  - Slow reads                                             46  - Slow writes                                            28  - Slow metadata ops                                       0 ================================================================================ PERFORMANCE ASSESSMENT ================================================================================ ✓ EXCELLENT: Average latency under 1ms - NFS is performing very well ================================================================================ BREAKDOWN BY OPERATION TYPE ================================================================================ File Operations:  Total time: 36.735s (68.2% of total)  Operations: 499,238  Average: 73.6µs  Errors: 885 (0.2%)  Slowest: read took 234.538ms Process/Thread:  Total time: 11.877s (22.1% of total)  Operations: 61,980  Average: 191.6µs  Errors: 553 (0.9%)  Slowest: futex took 28.602ms Metadata Operations:  Total time: 3.286s (6.1% of total)  Operations: 7,525  Average: 436.6µs  Errors: 3951 (52.5%)  Slowest: fstat took 9.441ms Directory Operations:  Total time: 479.873ms (0.9% of total)  Operations: 309  Average: 1.553ms  Errors: 2 (0.6%)  Slowest: mkdir took 6.502ms Path Operations:  Total time: 68.379ms (0.1% of total)  Operations: 32  Average: 2.137ms  Slowest: rename took 3.716ms Memory Mapping:  Total time: 35.357ms (0.1% of total)  Operations: 291  Average: 121.5µs  Slowest: munmap took 14.876ms Sync Operations:  Total time: 21.175ms (0.0% of total)  Operations: 3  Average: 7.058ms  Slowest: fsync took 13.304ms ================================================================================ TOP 10 SLOWEST OPERATIONS ================================================================================ NFS-Related Slow Operations: --------------------------------------------------------------------------------  Duration Syscall      Details --------------------------------------------------------------------------------  11.317ms read         6, "rust Root Certification Authorit"..., 4096  26.012ms read         5, "\343/\345\313\301\267\374<\300\202\34\fw\257D\...  23.879ms read         5, "\313ID/\355<\243w\36\27N)\204\361\373Z\300\301...  20.824ms read         5, "\27\3\3\5k", 5  23.476ms read         5, "\27\3\3\5k", 5  21.087ms read         5, "\333\345\333\203M\247?\326\371 +[\326\341\16Er...  23.844ms read         5, "\27\3\3\5k", 5  20.906ms read         5, "\27\3\3\5k", 5  23.917ms read         5, "\27\3\3\5k", 5  24.854ms read         5, "\348\300\16\363\330F\27\10\262\177\5;\374\213\... Other Slow Operations (for context): --------------------------------------------------------------------------------  23.201ms pselect6  11.997ms setsockopt  36.037ms pselect6  35.509ms pselect6  50.067ms pselect6 ================================================================================ FAILED OPERATIONS (First 10) ================================================================================ access: "/etc/ld.so.preload", R_OK... access: "/etc/gitconfig", R_OK... access: "/home/foobarbaz/.config/git/config", R_OK... access: "/home/foobarbaz/.gitconfig", R_OK... access: "/etc/gitconfig", R_OK... access: "/home/foobarbaz/.config/git/config", R_OK... access: "/home/foobarbaz/.gitconfig", R_OK... openat: AT_FDCWD, "/usr/share/locale/en_US.UTF-8/LC_MESSAGES/git.mo"... openat: AT_FDCWD, "/usr/share/locale/en_US.utf8/LC_MESSAGES/git.mo",... openat: AT_FDCWD, "/usr/share/locale/en_US/LC_MESSAGES/git.mo", O_RD... $ ```