今天服务器上搜集日志 filebeat报错内存溢出 上服务器发现了奇怪的现象.日志文件大小显示不一致
报错如下
2019-12-12T11:49:50.417+0800 INFO input/input.go:114 Starting input of type: log; ID: 7944001240001573786 2019-12-12T11:49:50.417+0800 INFO crawler/crawler.go:106 Loading and starting Inputs completed. Enabled inputs: 1 2019-12-12T11:49:50.417+0800 INFO cfgfile/reload.go:150 Config reloader started 2019-12-12T11:49:50.417+0800 INFO cfgfile/reload.go:205 Loading of config files completed. 2019-12-12T11:49:50.420+0800 INFO log/harvester.go:255 Harvester started for file: /data/module/core/config/execute.log 2019-12-12T11:49:50.423+0800 INFO log/harvester.go:255 Harvester started for file: /data/module/core/coupon/execute.log 2019-12-12T11:49:50.430+0800 INFO log/harvester.go:255 Harvester started for file: /data/module/core/course/execute.log 2019-12-12T11:49:50.443+0800 INFO log/harvester.go:255 Harvester started for file: /data/module/core/goods/execute.log 2019-12-12T11:49:50.453+0800 INFO log/harvester.go:255 Harvester started for file: /data/module/core/oauth/execute.log 2019-12-12T11:49:50.476+0800 INFO log/harvester.go:255 Harvester started for file: /data/module/core/order/execute.log 2019-12-12T11:49:50.483+0800 INFO log/harvester.go:255 Harvester started for file: /data/module/core/user/execute.log fatal error: runtime: out of memory
runtime stack: runtime.throw(0x17bae61, 0x16) /usr/local/go/src/runtime/panic.go:616 +0x81 runtime.sysMap(0xc5a40b0000, 0x1e200000, 0x21fa200, 0x2213658) /usr/local/go/src/runtime/mem_linux.go:216 +0x20a runtime.(*mheap).sysAlloc(0x21f9a60, 0x1e200000, 0x0) /usr/local/go/src/runtime/malloc.go:470 +0xd4 runtime.(*mheap).grow(0x21f9a60, 0xf0fe, 0x0) /usr/local/go/src/runtime/mheap.go:907 +0x60 runtime.(*mheap).allocSpanLocked(0x21f9a60, 0xf0fe, 0x2213668, 0x7fff537e6960) /usr/local/go/src/runtime/mheap.go:820 +0x301 runtime.(*mheap).alloc_m(0x21f9a60, 0xf0fe, 0xa00101, 0xc41fbb28ff) /usr/local/go/src/runtime/mheap.go:686 +0x118 runtime.(*mheap).alloc.func1() /usr/local/go/src/runtime/mheap.go:753 +0x4d runtime.(*mheap).alloc(0x21f9a60, 0xf0fe, 0x2000101, 0x100000000a0f4fc) /usr/local/go/src/runtime/mheap.go:752 +0x8a runtime.largeAlloc(0x1e1fc000, 0x100, 0xc42055bb08) /usr/local/go/src/runtime/malloc.go:826 +0x94 runtime.mallocgc.func1() /usr/local/go/src/runtime/malloc.go:721 +0x46 runtime.systemstack(0x0) /usr/local/go/src/runtime/asm_amd64.s:409 +0x79 runtime.mstart() /usr/local/go/src/runtime/proc.go:1175
goroutine 94 [running]: runtime.systemstack_switch() /usr/local/go/src/runtime/asm_amd64.s:363 fp=0xc42055ba18 sp=0xc42055ba10 pc=0xa53190 runtime.mallocgc(0x1e1fc000, 0x0, 0x4000, 0x4000) /usr/local/go/src/runtime/malloc.go:720 +0x8a2 fp=0xc42055bab8 sp=0xc42055ba18 pc=0xa0bad2 runtime.growslice(0x15ab540, 0xc5608ee000, 0x18194000, 0x18196000, 0x18198000, 0x29009fe1, 0x13bdea84b, 0xc42055bbe8) /usr/local/go/src/runtime/slice.go:172 +0x21d fp=0xc42055bb20 sp=0xc42055bab8 pc=0xa3d6ad github.com/elastic/beats/libbeat/common/streambuf.(*Buffer).doAppend(0xc420164730, 0xc4289ae000, 0x4000, 0x4000, 0x4001, 0xffffffffffffffff, 0x1, 0xc4289ae000) /go/src/github.com/elastic/beats/libbeat/common/streambuf/streambuf.go:160 +0x3fb fp=0xc42055bba8 sp=0xc42055bb20 pc=0xe9932b github.com/elastic/beats/libbeat/common/streambuf.(*Buffer).Append(0xc420164730, 0xc4289ae000, 0x4000, 0x4000, 0x4000, 0x0) /go/src/github.com/elastic/beats/libbeat/common/streambuf/streambuf.go:175 +0x57 fp=0xc42055bbf8 sp=0xc42055bba8 pc=0xe99487 github.com/elastic/beats/filebeat/reader/readfile.(*LineReader).advance(0xc42021abd0, 0x0, 0x0) /go/src/github.com/elastic/beats/filebeat/reader/readfile/line.go:129 +0x1a1 fp=0xc42055bc88 sp=0xc42055bbf8 pc=0x14187f1 github.com/elastic/beats/filebeat/reader/readfile.(*LineReader).Next(0xc42021abd0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0) |
ll -h
du -sh *
ls -ls
转载了下面的文章 帮助自己理解了
背景
确切地说,不是收到的自动告警短信或者邮件告诉我某机器上的磁盘满了,而是某同学人肉发现该机器写不了新文件才发现该问题的. 说明我司告警服务还不太稳定 :)
第一次出现该问题时, 我的处理方式是: 先删了 /tmp/ 目录, 空闲出部分空间, 然后检查下几个常用的用户目录, 最终发现某服务A的日志文件(contentutil.log)占用了好几个大G, 询问相关开发人员后确定该日志文件不需要压缩备份, 所以可直接删除, 于是 rm contentutil.log 之后就天真地认为万事大吉了…(不懂为啥当初没 df 再看看)
然而, 大约xx天后, 发现该机器磁盘又满了, 惊呼奇怪咋这么快又满了. 最终发现是上次 rm contentutil.log 后, 占用好几个大G的contentutil.log 一直被服务A的进程打开了, rm 后空间并没有释放.
rm 其实是删除该文件名到文件真正保存到磁盘位置的链接, 此时该文件句柄还被服务A打开, 因此对应的数据并没有被回收, 其实可以理解为 GC 里面的引用计数, rm 只是减少了引用计数, 并没有真正的进行释放内存, 当引用计数为0的时候, OS 内核才会释放空间, 供其他进程使用. 所以当A进程停止(文件句柄的引用计数会变为0)或者重启后, 占用的存储空间才被释放(从某种程度上讲说明该服务一直很稳定, 可以连续跑很久不出故障~ 微笑脸).
(tip: 如果不知道具体进程或文件名的话:lsof | grep deleted,这样会查找所有被删除的但是文件句柄没有释放的文件和相应的进程,然后再kill掉进程或者重启进程即可).
后来, 白老板告知可以用修改文件内容的方式在不用重启进程的情况下释放空间.
du vs ls
前两天该问题又出现了, 该服务A的日志文件(contentutil.log)占用了约7.6G(请原谅我们没有对该服务的日志做logrotate)。这一次学聪明了, 直接用echo 'hello' > contentutil.log, 然后 df 确认磁盘空间确实已经释放, 心想着这次可以 Happy 了, 突然手贱执行了下 ls 和 du, 有了以下结果:
[root@xxx shangtongdai-content-util]# ls -lah contentutil.log |
反正我看到这样的结果是百思不得其解, 如果你已经明确为什么会产生这样的结果, 那就不用继续往下看了.
可以明确的是, 这里的 ls 和 du 结果肯定代表不同的含义, 具体原因不详, 在查阅相关资料和咨询强大的票圈后了解到, 这大概与文件空洞和稀疏文件(holes in ‘sparse’ files)相关.
ls 的结果是 apparent sizes, 我的理解是文件长度, 就类似文件系统中 file 这个数据结构中的定义文件长度的这个字段, du 的结果 disk usage, 即真正占用存储空间的大小, 且默认度量单位是 block. (apparent sizes 和 disk usage 说法摘自 man du 中的 --apparent-size 部分)
给出一个具体的示例:
// Mac OS 10.11.6 (15G1004) |
上面示例中, 文件 1B.log 内容仅仅包含一个字母”a”, 文件长度为1个字节, 前面的 8 为占用的存储空间 8 个 block, (ls -s 的结果跟 du 的结果等价, 都是实际占用磁盘的空间), 为什么1个字节的文件需要占用8个 block 呢, 可以这样理解, block 为磁盘存储的基本的单位, 方便磁盘寻址等(这里说的基本单位应该是磁盘物理结构单位例如一个扇区/柱面等, 对应一个物理单位), 而此处的block可以理解为一个逻辑单位, 且一个文件除了包括数据外, 还需要存储描述此文件的其他信息, 因此包含1个字节的文件实际在磁盘中占用的存储空间不止1个字节. 默认情况下, Mac中1个逻辑block中是 512 字节, 因此 du -h 结果是 8 * 512 = 4096 = 4.0K.
If the environment variable BLOCKSIZE is set, and the -k option is not specified, the block counts will be displayed in units of that size block. If BLOCKSIZE is not set, and the -k option is not specified, the block counts will be displayed in 512-byte blocks. (man du)
因此, 通常情况下, ls 的结果应该比 du的结果更小(都指用默认的参数执行, 调整参数可使其表达含义相同), 然而上面跑服务 A 的机器上 contentutil.log 的对比结果是 7.6G vs. 2.3M, 仍然无法理解了.
沿着 man du 可以看到:
although the apparent size is usually smaller, it may be larger due to holes in (‘sparse’) files, internal fragmentation, indirect blocks, and the like
即因contentutil.log是一个稀疏文件, 虽然其文件长度很大, 到7.6G了, 然而其中包含大量的holes并不占用实际的存储空间.
下面用一个具体的例子来复现以上遇到的问题. 注意以下例子为 Linux version 2.6.32 (Red Hat 4.4.7)中运行结果, 且在 Mac 中并不能复现(后文有指出为什么我的Mac不能复现).
// 从标准输入中读取 count=0 个block, 输出到 sparse-file 中, |
此时若用 vim 打开该文件, 用二进制形式查看 (tip :%!xxd 可以更改当前文件显示为2进制形式), 能看到里面的内容全是0. 或者直接用od命令查看2进制.
// vim 二进制查看 |
实际上, Sparse 文件是并不占用磁盘存储空间的, 那为什么能看到文件里面包含很多0? 因为当在读取稀疏文件的时候, 文件系统根据文件的 metadata(就是前面所指描述文件的这个数据结构)自动用0填充[ref Wiki]; Wiki上还说, 现代的不少文件系统都支持 Sparse 文件, 包括 Unix 及其变种和 NTFS, 然而Apple File System(APFS)不支持, 因此我在我的 Mac 上用 du 查看占用空间与 ls 的结果一致. 传闻指出 Apple 在今年6月的 WWWC 上宣称支持 Sparse 文件. (貌似目前我的系统版本还不支持)
// In Mac |
以上是用 dd 等命令创建稀疏文件, 也有同学用 c 代码实现了相同的功能. 其实就是写文件的时候, 改变下当前文件写指针. 前面遇到的问题就应该类似.
#include <stdio.h> |
以上先将”hello”写入filetest.log, 然后改变文件指针到1024*1024*10(相当于文件长度这个字段变大了), gcc 编译后运行结果文件详情如下:
[root@localhost ~]# ls -ls filetest.log |
解释下结果: 文件长度应该是 “hello” 加上 “\n” 共6个字节*2 = 12, 再加上1024*1024*10个字节, 即为ls产生的结果10485772个字节约11M, 而du的结果为8个block也为8k(这台机器上的block大小与前面的Mac不一样, 这里是1024).
Display values are in units of the first available SIZE from –block-size, and the DU_BLOCK_SIZE, BLOCK_SIZE and BLOCKSIZE environment variables. Otherwise, units default to 1024 bytes (or 512 if POSIXLY_CORRECT is set. (du --help)
总结
总结一下: 出现以上问题说明自己对一些基础掌握得尚不牢固, 比如
rm 某文件后, 文件占用的磁盘空间并不是立即释放, 而是其句柄没有被任意一个进程引用时才回收;
ls/du 命令结果的具体含义;
稀疏文件.