问题排查方法
客户端日志
对于宿主机挂载,客户端日志默认为 /var/log/juicefs.log
,当使用 JuiceFS 出现问题时,首先查看客户端日志。而如果日志中没有明显异常,可以为挂载命令添加 --verbose
参数(支持平滑重新挂载),输出更为丰富的 DEBUG 日志。
不同 JuiceFS 客户端获取日志的方式不同,以下分别介 绍。
宿主机挂载点
在挂载命令中用 --log=<log_path>
指定日志储存路径,默认为 /var/log/juicefs.log
或 ~/.juicefs/log/juicefs.log
,具体取决于执行用户。
可以用 grep
命令过滤不同等级日志做性能分析或者故障诊断:
grep 'ERROR\|FATAL' /var/log/juicefs.log
Kubernetes CSI 驱动
根据你使用的 JuiceFS CSI 驱动版本会有不同的获取日志的方式,参考 CSI 驱动文档。
S3 网关
S3 网关仅支持在前台运行,因此客户端日志会直接输出到终端。如果你是在 Kubernetes 中部署 S3 网关,需要查看对应 pod 的日志。
Hadoop Java SDK
使用 JuiceFS Hadoop Java SDK 的应用进程(如 Spark executor)的日志中会包含 JuiceFS 客户端日志,因为和应用自身产生的日志混杂在一起,需要通过 juicefs
关键词来过滤筛选。
文件系统访问日志
JuiceFS 在每个挂载点的根目录下提供了文件名为 .oplog
(在 4.7.0 及以上又名 .accesslog
)和 .ophistory
的纯文本格式虚拟文件,记录了实时的文件系统访问日志,如操作类型、UID/GID、文件 inode 及其花费的时间。访问日志可以有多种用途,如性能分析、审计、故障诊断。
下方将会介绍的 juicefs profile
命令正是根据访问日志统计各种文件系统操作,在命令行汇总呈现统计信息。你可以使用该命令快速统计并判断出你的应用对 于文件系统的访问模式,评估访问性能。
日志格式
我们选取了一些常见的文件系统操作,将访问日志的样例与格式说明在下方进行示范,日志中用 inode 来表示文件,如果需要从 inode 反查文件详细信息,可以使用 juicefs info [INODE]
。
# 大体上格式如下,不同类型日志稍有区别:
# [UID,GID,PID] [调用方法] [输入参数(不同方法参数有别)]: [OK] [排查信息] <耗时(秒)>
# open,输入参数 (inode, flags)
[uid:0,gid:0,pid:1631098] open (38597810,0x8000): OK (38597810,[-rw-r--r--:0100644,1,0,0,1650446639,1650446639,1650446639,212]) (direct_io:0,keep_cache:1) [handle:00007869] <0.010293>
# read,输入参数 (inode, size, offset, file-handler)
[uid:0,gid:0,pid:0] read (148199375,69632,1439510528,18333): OK (69632) <0.001047>
# getattr,输入参数 (inode)
[uid:0,gid:0,pid:1631098] getattr (1): OK (1,[drwxrwxrwx:0040777,19977521,0,0,1634886025,1663052916,1663052916,9265059409920]) <0.000002>
# statfs,输入参数 (inode)
[uid:0,gid:0,pid:1240206] statfs (1): OK (47474945257472,62476217520128,1165873,4293801422) <0.000345>
# setattr,输入参数 (inode, setmask, mode)
[uid:0,gid:0,pid:1631098] setattr (45758905,0x1,[mode=-rw-r--r--:00644;]): OK (45758905,[-rw-r--r--:0100644,1,0,0,1664165438,1664165438,1664165438,4096]) <0.011076>
# create,输入参数 (parent-inode, name, mode, umask)
[uid:0,gid:0,pid:1631098] create (1,.temp.sh.swp,-rw-------:0100600,00000,0x280C2): OK (45758905,[-rw-------:0100600,1,0,0,1664165438,1664165438,1664165438,0]) [handle:00007868] <0.011117>
# write,输入参数 (inode, size, offset, file-handler)
[uid:0,gid:0,pid:1631098] write (45758905,4096,0,18333): OK <0.000040>
# unlink,输入参数 (parent-inode, name)
[uid:0,gid:0,pid:1631098] unlink (1,temp.sh~): OK <0.011033>
# flush,输入参数 (inode, file-handler)
[uid:0,gid:0,pid:1631098] flush (45758905,18333): OK <0.030459>
不同 JuiceFS 客户端获取访问日志的方式不同,以下分别介绍。
宿主机挂载点
假设 JuiceFS 挂载点为 /jfs
:
cat /jfs/.oplog
及cat /jfs/.accesslog
:输出实时的操作日志,其中.accesslog
仅仅是.oplog
的别名。cat /jfs/.ophistory
:该文件保留最近的日志,不超过 15M。
Kubernetes CSI 驱动
在 mount pod 内,JuiceFS 挂载点路径为 /jfs/<pv_volumeHandle>
,操作命令示范命令如下:
# 首先找到应用容器对应的 mount pod,默 认名称中会含有 PVC 名,根据实际情况调整:
kubectl -n kube-system get pod | grep juicefs | grep [pvc-name]
# 也可以罗列出所有 mount pod,然后自行查找判断:
kubectl -n kube-system get pod -l app.kubernetes.io/name=juicefs-mount
# 钻进容器, 打印访问日志:
kubectl -n kube-system exec juicefs-[node]-pvc-d4b8fb4f-2c0b-48e8-a2dc-530799435373 -- cat /jfs/pvc-d4b8fb4f-2c0b-48e8-a2dc-530799435373/.oplog
Hadoop Java SDK
需要在 JuiceFS Hadoop Java SDK 的客户端配置中新增 juicefs.access-log
配置项,指定访问日志输出的路径,默认不输出访问日志。
实时统计数据
JuiceFS 在每个挂载点的根目录下提供了一个文件名为 .stats
的纯文本格式虚拟文件,记录了实时的统计数据。在进行故障诊断和分析的时候,查看这个文件里面的统计数据将会非常有帮助。这些统计数据也可以通过 JSON API 或者 Prometheus API 收集,参考「监控」文档。
不同 JuiceFS 客户端获取实时统计数据的方式不同,以下分别介绍。
宿主机挂载点
假设 JuiceFS 挂载点为 /jfs
:
# 查看 CPU 和内存占用:
cat /jfs/.stats | grep usage
# 查看运行时间:
cat /jfs/.stats | grep uptime
# 查看对象存储的各项操作请求计数:
cat /jfs/.stats | grep object
# 查看对象存储读写数据量:
cat /jfs/.stats | grep _bytes
Kubernetes CSI 驱动
在 mount pod 内,JuiceFS 挂载点路径为 /jfs/<pv_volumeHandle>
,示范命令如下:
# 首先找到应用容器对应的 mount pod,默认名称中会含有 PVC 名,根据实际情况调整:
kubectl -n kube-system get pod | grep juicefs | grep [pvc-name]
# 也可以罗列出所有 mount pod,然后自行查找判断:
kubectl -n kube-system get pod -l app.kubernetes.io/name=juicefs-mount
# 钻进容器,打印访问日志:
kubectl -n kube-system exec juicefs-[node]-pvc-d4b8fb4f-2c0b-48e8-a2dc-530799435373 -- cat /jfs/pvc-d4b8fb4f-2c0b-48e8-a2dc-530799435373/.stats
实时性能监控
基于上方介绍的「文件系统访问日志」和「实时统计数据」,JuiceFS 客户端提供 profile
和 stats
两个子命令来对性能数据进行可视化呈现。
juicefs profile
juicefs profile
会对「文件系统访问日志」进行汇总,根据日志的统计信息显示各个文件系统调用的耗时:
该命 令提供实时和回放两种诊断模式,实时模式下会现场读取挂载点下的文件系统访问日志来进行计算,而回放模式则可以对预先收集的日志进行回放分析。
实时模式示范如下:
juicefs profile MOUNTPOINT
在调试或分析性能问题时,更实用的做法通常是先记录访问日志,然后重放:
# 预先收集日志
cat /jfs/.accesslog > /tmp/jfs-oplog
# 性能问题复现后,重放日志,分析各调用耗时,找出性能瓶颈
juicefs profile -f /tmp/jfs-oplog
juicefs stats
stats
命令通过读取 JuiceFS 客户端的性能数据,以类似 Linux dstat
工具的形式实时打印各个指标的每秒变化情况:
各个板块指标介绍:
usage
cpu
:进程的 CPU 使用率。mem
:进程的物理内存使用量。buf
:进程已使用的读写缓冲区大小,如果该数值逼近甚至超过客户端所设置的--buffer-size
,说明读写缓冲区空间不足,需要视情况扩大,或者降低应用读写负载。
fuse
ops
/lat
:通过 FUSE 接口处理的每秒请求数及其平均时延,单位为毫秒。read
/write
:通过 FUSE 接口处理的读写带宽。需要注意 FUSE 视角统计的读数据量,未必是客户端真实的读带宽:文件读取后,数据会进入内核页缓存,下次读取时不会再经过 FUSE,导致 FUSEread
比实际值低,甚至完全为 0。
meta
ops
/lat
:每秒处理的元数据请求数和平均时延,单位为毫秒。注意部分能在缓存中直接处理的元数据请求未列入统计,以更好地体现客户端与元数据引擎交互的耗时。
blockcache
blockcache
代表本地数据缓存,如果读请求已经被内核缓存,那么流量将不会体现在 blockcache
相关指标下。因此如果反复读取相同文件,却发现持续产生 blockcache
流量,说明文件始终未能被内核页缓存收录,考虑往该方向排查(比如内存吃紧,不足以缓存更多文件)。
read
/write
:客户端本地数据缓存的每秒读写流量。
object
object
代表与对象存储相关指标,在缓存场景下,读请求穿透到对象存储,将会明显降低读性能,可以用该指标来断定数据是否完整缓存。另一方面,通过对比 object.get
和 fuse.read
的数据,也能初步判断读放大的情况。
get
/put
:客户端与对象存储交互的GetObject
/PutObject
每秒流量。
用 pprof 获取运行时信息
JuiceFS 客户端默认会通过 pprof 在本地监听一个 TCP 端口用以获取运行时信息,如 Goroutine 堆栈信息、CPU 性能统计、内存分配统计。你可以通过挂载点下的 .config
文件查看当前 JuiceFS 客户端监听的具体端口号:
# 假设挂载点是 /jfs
$ cat /jfs/.config | grep 'DebugAgent'
"DebugAgent": "127.0.0.1:6064",
默认 pprof 监听的端口号范围是从 6060 开始至 6099 结束,从上面的示例中可以看到实际的端口号是 6064。在获取到监听端口号以后就可以通过 http://localhost:<port>/debug/pprof
地址查看所有可供查询的运行时信息,一些重要的运行时信息如下:
- Goroutine 堆栈信息:
http://localhost:<port>/debug/pprof/goroutine?debug=1
- CPU 性能统计:
http://localhost:<port>/debug/pprof/profile?seconds=30
- 内存分配统计:
http://localhost:<port>/debug/pprof/heap
为了便于分析这些运行时信息,可以将它们保存到本地,例如:
curl 'http://localhost:<port>/debug/pprof/goroutine?debug=1' > juicefs.goroutine.txt
curl 'http://localhost:<port>/debug/pprof/profile?seconds=30' > juicefs.cpu.pb.gz
curl 'http://localhost:<port>/debug/pprof/heap' > juicefs.heap.pb.gz
你也可以使用 juicefs doctor
命令自动收集这些运行时信息并保存到本地,默认保存到当前目录下的 debug
目录中,例如:
juicefs doctor /jfs
关于 juicefs doctor
命令的更多信息,请查看命令参考。
如果你安装了 go
命令,那么可以通过 go tool pprof
命令直接分析,例如分析 CPU 性能统计:
$ go tool pprof 'http://localhost:<port>/debug/pprof/profile?seconds=30'
Fetching profile over HTTP from http://localhost:<port>/debug/pprof/profile?seconds=30
Saved profile in /Users/xxx/pprof/pprof.samples.cpu.001.pb.gz
Type: cpu
Time: Dec 17, 2021 at 1:41pm (CST)
Duration: 30.12s, Total samples = 32.06s (106.42%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 30.57s, 95.35% of 32.06s total
Dropped 285 nodes (cum <= 0.16s)
Showing top 10 nodes out of 192
flat flat% sum% cum cum%
14.73s 45.95% 45.95% 14.74s 45.98% runtime.cgocall
7.39s 23.05% 69.00% 7.41s 23.11% syscall.syscall
2.92s 9.11% 78.10% 2.92s 9.11% runtime.pthread_cond_wait
2.35s 7.33% 85.43% 2.35s 7.33% runtime.pthread_cond_signal
1.13s 3.52% 88.96% 1.14s 3.56% runtime.nanotime1
0.77s 2.40% 91.36% 0.77s 2.40% syscall.Syscall
0.49s 1.53% 92.89% 0.49s 1.53% runtime.memmove
0.31s 0.97% 93.86% 0.31s 0.97% runtime.kevent
0.27s 0.84% 94.70% 0.27s 0.84% runtime.usleep
0.21s 0.66% 95.35% 0.21s 0.66% runtime.madvise
也可以将运行时信息导出为可视化图表,以更加直观的方式进行分析。可视化图表支持导出为多种格式,如 HTML、PDF、SVG、PNG 等。例如导出内存分配统计信息为 PDF 文件的命令如下:
导出为可视化图表功能依赖 Graphviz,请先将它安装好。
go tool pprof -pdf 'http://localhost:<port>/debug/pprof/heap' > juicefs.heap.pdf
关于 pprof 的更多信息,请查看官方文档。
JuiceFS Doctor
如果上边的排查手段未能帮助解决你的问题,Juicedata 团队可能会要求你用 juicefs doctor
这个命令收集更为丰富的排查信息,将结果发给我们进行排查解决。