search

kahing / goofys

a high-performance, POSIX-ish Amazon S3 file system written in Go
Apache License 2.0
5.22k stars 523 forks source link

Memory Leak? #276

Open kyledayton opened 6 years ago

kyledayton commented 6 years ago

Using goofys version 0.19.0-943e017724ea820eb4185419ef3c41d6f921a324

fatal error: runtime: cannot allocate memory

runtime stack:
runtime.throw(0x9ae294, 0x1f)
    /usr/local/go/src/runtime/panic.go:605 +0x95
runtime.persistentalloc1(0x4000, 0x0, 0xce1578, 0x7ff964261060)
    /usr/local/go/src/runtime/malloc.go:989 +0x2bf
runtime.persistentalloc.func1()
    /usr/local/go/src/runtime/malloc.go:942 +0x45
runtime.systemstack(0x7ff962254c50)
    /usr/local/go/src/runtime/asm_amd64.s:360 +0xab
runtime.persistentalloc(0x4000, 0x0, 0xce1578, 0xcc8aa8)
    /usr/local/go/src/runtime/malloc.go:941 +0x99
runtime.(*fixalloc).alloc(0xccb770, 0x1)
    /usr/local/go/src/runtime/mfixalloc.go:80 +0x108
runtime.(*mheap).allocSpanLocked(0xcc82a0, 0x1, 0xce1548, 0x7ff951387e58)
    /usr/local/go/src/runtime/mheap.go:825 +0x15c
runtime.(*mheap).alloc_m(0xcc82a0, 0x1, 0x20000000e, 0x7ff951387e58)
    /usr/local/go/src/runtime/mheap.go:666 +0x118
runtime.(*mheap).alloc.func1()
    /usr/local/go/src/runtime/mheap.go:733 +0x4d
runtime.systemstack(0x7ff962254da0)
    /usr/local/go/src/runtime/asm_amd64.s:360 +0xab
runtime.(*mheap).alloc(0xcc82a0, 0x1, 0x7ff95101000e, 0x7ff951387e58)
    /usr/local/go/src/runtime/mheap.go:732 +0xa1
runtime.(*mcentral).grow(0xcc9970, 0x0)
    /usr/local/go/src/runtime/mcentral.go:232 +0x94
runtime.(*mcentral).cacheSpan(0xcc9970, 0x7ff951387e58)
    /usr/local/go/src/runtime/mcentral.go:106 +0x33a
runtime.(*mcache).refill(0x7ff964259000, 0x10000000043460e, 0x7ff951387e58)
    /usr/local/go/src/runtime/mcache.go:123 +0xa4
runtime.(*mcache).nextFree.func1()
    /usr/local/go/src/runtime/malloc.go:557 +0x32
runtime.systemstack(0xc42001c000)
    /usr/local/go/src/runtime/asm_amd64.s:344 +0x79
runtime.mstart()
    /usr/local/go/src/runtime/proc.go:1135

goroutine 6146963 [running]:
runtime.systemstack_switch()
    /usr/local/go/src/runtime/asm_amd64.s:298 fp=0xc484e872c0 sp=0xc484e872b8 pc=0x4579a0
runtime.(*mcache).nextFree(0x7ff964259000, 0xe, 0xc484e873e0, 0x75575a, 0x907a20)
    /usr/local/go/src/runtime/malloc.go:556 +0xa9 fp=0xc484e87318 sp=0xc484e872c0 pc=0x411b89
runtime.mallocgc(0x60, 0x967840, 0x1, 0xcdfb60)
    /usr/local/go/src/runtime/malloc.go:711 +0x6f0 fp=0xc484e873c0 sp=0xc484e87318 pc=0x412450
runtime.newobject(0x967840, 0xc48bb3e8c0)
    /usr/local/go/src/runtime/malloc.go:840 +0x38 fp=0xc484e873f0 sp=0xc484e873c0 pc=0x412798
github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/private/protocol/xml/xmlutil.XMLToStruct(0xc48935ca00, 0xc48bb3e800, 0xc48bb24d14, 0x5, 0xce0900)
    /home/khc/Code/go/src/github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/private/protocol/xml/xmlutil/xml_to_struct.go:77 +0x4af fp=0xc484e875f0 sp=0xc484e873f0 pc=0x75509f
github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/private/protocol/xml/xmlutil.XMLToStruct(0xc48935ca00, 0xc48bb3e440, 0xc48bb24cc8, 0x8, 0xc47a537c98)
    /home/khc/Code/go/src/github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/private/protocol/xml/xmlutil/xml_to_struct.go:70 +0x404 fp=0xc484e877f0 sp=0xc484e875f0 pc=0x754ff4
github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/private/protocol/xml/xmlutil.XMLToStruct(0xc48935ca00, 0xc47a538580, 0xc47a51b780, 0x10, 0xce0900)
    /home/khc/Code/go/src/github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/private/protocol/xml/xmlutil/xml_to_struct.go:70 +0x404 fp=0xc484e879f0 sp=0xc484e877f0 pc=0x754ff4
github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/private/protocol/xml/xmlutil.XMLToStruct(0xc48935ca00, 0x0, 0xc47a53d000, 0x58, 0x96ddc0)
    /home/khc/Code/go/src/github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/private/protocol/xml/xmlutil/xml_to_struct.go:70 +0x404 fp=0xc484e87bf0 sp=0xc484e879f0 pc=0x754ff4
github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/private/protocol/xml/xmlutil.UnmarshalXML(0x96d700, 0xc489392af0, 0xc48935ca00, 0x0, 0x0, 0x1000, 0x6)
    /home/khc/Code/go/src/github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/private/protocol/xml/xmlutil/unmarshal.go:18 +0x49 fp=0xc484e87cd0 sp=0xc484e87bf0 pc=0x752189
github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/private/protocol/restxml.Unmarshal(0xc47a518800)
    /home/khc/Code/go/src/github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/private/protocol/restxml/restxml.go:51 +0x22e fp=0xc484e87dd0 sp=0xc484e87cd0 pc=0x75f87e
github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/aws/request.(*HandlerList).Run(0xc47a5189d0, 0xc47a518800)
    /home/khc/Code/go/src/github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/aws/request/handlers.go:164 +0x9d fp=0xc484e87e68 sp=0xc484e87dd0 pc=0x72610d
github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/aws/request.(*Request).Send(0xc47a518800, 0x0, 0x0)
    /home/khc/Code/go/src/github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/aws/request/request.go:512 +0x491 fp=0xc484e87f20 sp=0xc484e87e68 pc=0x728db1
github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/service/s3.(*S3).ListObjects(0xc42000e078, 0xc47a5382c0, 0x7e04a6, 0xc420172750, 0xc89020)
    /home/khc/Code/go/src/github.com/kahing/goofys/vendor/github.com/aws/aws-sdk-go/service/s3/api.go:3887 +0x4d fp=0xc484e87f58 sp=0xc484e87f20 pc=0x77712d
github.com/kahing/goofys/internal.(*DirHandle).listObjects.func2()
    /home/khc/Code/go/src/github.com/kahing/goofys/internal/dir.go:250 +0x114 fp=0xc484e87fe0 sp=0xc484e87f58 pc=0x870414
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:2337 +0x1 fp=0xc484e87fe8 sp=0xc484e87fe0 pc=0x45a591
created by github.com/kahing/goofys/internal.(*DirHandle).listObjects
    /home/khc/Code/go/src/github.com/kahing/goofys/internal/dir.go:260 +0x599

goroutine 1 [select, 4803 minutes]:
github.com/jacobsa/fuse.(*MountedFileSystem).Join(0xc42048c540, 0xc88fa0, 0xc420014028, 0x1, 0xc420174000)
    /home/khc/Code/go/src/github.com/jacobsa/fuse/mounted_file_system.go:43 +0x100
main.main.func1(0xc420096840, 0x0, 0x0)
    /home/khc/Code/go/src/github.com/kahing/goofys/main.go:235 +0x340
github.com/urfave/cli.HandleAction(0x8e2020, 0xc4200c6c40, 0xc420096840, 0x0, 0x0)
    /home/khc/Code/go/src/github.com/urfave/cli/app.go:490 +0xd2
github.com/urfave/cli.(*App).Run(0xc4201149c0, 0xc4200100a0, 0xa, 0xa, 0x0, 0x0)
    /home/khc/Code/go/src/github.com/urfave/cli/app.go:264 +0x635
main.main()
    /home/khc/Code/go/src/github.com/kahing/goofys/main.go:246 +0x166

goroutine 5 [syscall, 4803 minutes]:
os/signal.signal_recv(0x0)
    /usr/local/go/src/runtime/sigqueue.go:131 +0xa6
os/signal.loop()
    /usr/local/go/src/os/signal/signal_unix.go:22 +0x22
created by os/signal.init.0
    /usr/local/go/src/os/signal/signal_unix.go:28 +0x41

goroutine 18 [semacquire, 4803 minutes]:
sync.runtime_notifyListWait(0xc42013c580, 0xc400000000)
    /usr/local/go/src/runtime/sema.go:507 +0x110
sync.(*Cond).Wait(0xc42013c570)
    /usr/local/go/src/sync/cond.go:56 +0x80
io.(*pipe).read(0xc42013c540, 0xc42041e000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/local/go/src/io/pipe.go:47 +0xc6
io.(*PipeReader).Read(0xc42000e0f0, 0xc42041e000, 0x1000, 0x1000, 0x1000, 0x1000, 0x0)
    /usr/local/go/src/io/pipe.go:130 +0x4c
bufio.(*Scanner).Scan(0xc420023738, 0x0)
    /usr/local/go/src/bufio/scan.go:207 +0xaf
github.com/sirupsen/logrus.(*Entry).writerScanner(0xc42017c960, 0xc42000e0f0, 0xc4204835e0)
    /home/khc/Code/go/src/github.com/sirupsen/logrus/writer.go:51 +0xab
created by github.com/sirupsen/logrus.(*Entry).WriterLevel
    /home/khc/Code/go/src/github.com/sirupsen/logrus/writer.go:43 +0x174

goroutine 20 [syscall]:
syscall.Syscall(0x0, 0x8, 0xc4204da018, 0x21000, 0xc42001c000, 0x21000, 0x0)
    /usr/local/go/src/syscall/asm_linux_amd64.s:18 +0x5
syscall.read(0x8, 0xc4204da018, 0x21000, 0x21000, 0xc42003ac01, 0x0, 0x0)
    /usr/local/go/src/syscall/zsyscall_linux_amd64.go:756 +0x55
syscall.Read(0x8, 0xc4204da018, 0x21000, 0x21000, 0x40000000050, 0x10, 0x10)
    /usr/local/go/src/syscall/syscall_unix.go:162 +0x49
internal/poll.(*FD).Read(0xc42017ce10, 0xc4204da018, 0x21000, 0x21000, 0x0, 0x0, 0x0)
    /usr/local/go/src/internal/poll/fd_unix.go:122 +0x125
os.(*File).read(0xc42000e188, 0xc4204da018, 0x21000, 0x21000, 0x95ea60, 0xc42001c000, 0x800004e4168)
    /usr/local/go/src/os/file_unix.go:216 +0x4e
os.(*File).Read(0xc42000e188, 0xc4204da018, 0x21000, 0x21000, 0x20, 0xc42003ada0, 0x412798)
    /usr/local/go/src/os/file.go:103 +0x6d
github.com/jacobsa/fuse/internal/buffer.(*InMessage).Init(0xc4204da000, 0xc83da0, 0xc42000e188, 0xcdf9a8, 0x941ea0)
    /home/khc/Code/go/src/github.com/jacobsa/fuse/internal/buffer/in_message.go:53 +0x70
github.com/jacobsa/fuse.(*Connection).readMessage(0xc42013c600, 0xc47a538200, 0x8d1420, 0xcdf9a8)
    /home/khc/Code/go/src/github.com/jacobsa/fuse/connection.go:318 +0x63
github.com/jacobsa/fuse.(*Connection).ReadOp(0xc42013c600, 0x9bddc8, 0xc4200c7160, 0xc42013c600, 0xc89020, 0xc47a535320, 0x8ba640)
    /home/khc/Code/go/src/github.com/jacobsa/fuse/connection.go:380 +0x6c
github.com/jacobsa/fuse/fuseutil.(*fileSystemServer).ServeOps(0xc4200c7160, 0xc42013c600)
    /home/khc/Code/go/src/github.com/jacobsa/fuse/fuseutil/file_system.go:104 +0x5f
github.com/jacobsa/fuse.Mount.func1(0xc830e0, 0xc4200c7160, 0xc42013c600, 0xc42000e100)
    /home/khc/Code/go/src/github.com/jacobsa/fuse/mount.go:90 +0x3f
created by github.com/jacobsa/fuse.Mount
    /home/khc/Code/go/src/github.com/jacobsa/fuse/mount.go:89 +0x4e8

goroutine 21 [select, 4803 minutes, locked to thread]:
runtime.gopark(0x9be960, 0x0, 0x9a1716, 0x6, 0x18, 0x1)
    /usr/local/go/src/runtime/proc.go:287 +0x12c
runtime.selectgo(0xc42003bf50, 0xc420402c60)
    /usr/local/go/src/runtime/select.go:395 +0x1149
runtime.ensureSigM.func1()
    /usr/local/go/src/runtime/signal_unix.go:511 +0x220
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:2337 +0x1

goroutine 22 [chan receive, 4803 minutes]:
main.registerSIGINTHandler.func1(0xc4201f3620, 0xc420172750, 0xc420174000)
    /home/khc/Code/go/src/github.com/kahing/goofys/main.go:50 +0x5c
created by main.registerSIGINTHandler
    /home/khc/Code/go/src/github.com/kahing/goofys/main.go:48 +0xff

goroutine 6146902 [IO wait]:
internal/poll.runtime_pollWait(0x7ff9641fdeb0, 0x72, 0x0)
    /usr/local/go/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc46eb7cf98, 0x72, 0xffffffffffffff00, 0xc856a0, 0xc81538)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:85 +0xae
internal/poll.(*pollDesc).waitRead(0xc46eb7cf98, 0xc43f402800, 0x400, 0x400)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc46eb7cf80, 0xc43f402800, 0x400, 0x400, 0x0, 0x0, 0x0)
    /usr/local/go/src/internal/poll/fd_unix.go:126 +0x18a
net.(*netFD).Read(0xc46eb7cf80, 0xc43f402800, 0x400, 0x400, 0xc42011bc00, 0x7ff964259000, 0x0)
    /usr/local/go/src/net/fd_unix.go:202 +0x52
net.(*conn).Read(0xc483e8b210, 0xc43f402800, 0x400, 0x400, 0x0, 0x0, 0x0)
    /usr/local/go/src/net/net.go:176 +0x6d
crypto/tls.(*block).readFromUntil(0xc486fa0090, 0x7ff9642023d0, 0xc483e8b210, 0x5, 0xc483e8b210, 0xc48938d020)
    /usr/local/go/src/crypto/tls/conn.go:488 +0x95
crypto/tls.(*Conn).readRecord(0xc489942700, 0x9bea17, 0xc489942820, 0x0)
    /usr/local/go/src/crypto/tls/conn.go:590 +0xe0
crypto/tls.(*Conn).Read(0xc489942700, 0xc484e7f000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/local/go/src/crypto/tls/conn.go:1134 +0x110
net/http.(*persistConn).Read(0xc486f47c20, 0xc484e7f000, 0x1000, 0x1000, 0x2, 0xc43bfd2e58, 0x2)
    /usr/local/go/src/net/http/transport.go:1391 +0x140
bufio.(*Reader).fill(0xc486f7b4a0)
    /usr/local/go/src/bufio/bufio.go:97 +0x11a
bufio.(*Reader).Peek(0xc486f7b4a0, 0x1, 0x0, 0x0, 0x0, 0xc489356a80, 0x0)
    /usr/local/go/src/bufio/bufio.go:129 +0x3a
net/http.(*persistConn).readLoop(0xc486f47c20)
    /usr/local/go/src/net/http/transport.go:1539 +0x185
created by net/http.(*Transport).dialConn
    /usr/local/go/src/net/http/transport.go:1186 +0xa2e

goroutine 6146904 [select]:
net/http.(*persistConn).readLoop(0xc486f479e0)
    /usr/local/go/src/net/http/transport.go:1654 +0x7a7
created by net/http.(*Transport).dialConn
    /usr/local/go/src/net/http/transport.go:1186 +0xa2e

goroutine 6146906 [IO wait]:
internal/poll.runtime_pollWait(0x7ff9600d0ea0, 0x72, 0x0)
    /usr/local/go/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc46eb7d098, 0x72, 0xffffffffffffff00, 0xc856a0, 0xc81538)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:85 +0xae
internal/poll.(*pollDesc).waitRead(0xc46eb7d098, 0xc48ad5c000, 0x8000, 0x8000)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc46eb7d080, 0xc48ad5c000, 0x8000, 0x8000, 0x0, 0x0, 0x0)
    /usr/local/go/src/internal/poll/fd_unix.go:126 +0x18a
net.(*netFD).Read(0xc46eb7d080, 0xc48ad5c000, 0x8000, 0x8000, 0x2, 0xe96, 0xa)
    /usr/local/go/src/net/fd_unix.go:202 +0x52
net.(*conn).Read(0xc483e8b218, 0xc48ad5c000, 0x8000, 0x8000, 0x0, 0x0, 0x0)
    /usr/local/go/src/net/net.go:176 +0x6d
crypto/tls.(*block).readFromUntil(0xc486fa0150, 0x7ff9642023d0, 0xc483e8b218, 0x5, 0xc483e8b218, 0xc48938ce70)
    /usr/local/go/src/crypto/tls/conn.go:488 +0x95
crypto/tls.(*Conn).readRecord(0xc489942a80, 0x9bea17, 0xc489942ba0, 0x0)
    /usr/local/go/src/crypto/tls/conn.go:590 +0xe0
crypto/tls.(*Conn).Read(0xc489942a80, 0xc48ab30000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
    /usr/local/go/src/crypto/tls/conn.go:1134 +0x110
net/http.(*persistConn).Read(0xc486f47b00, 0xc48ab30000, 0x1000, 0x1000, 0x2, 0xc458f0ae58, 0x2)
    /usr/local/go/src/net/http/transport.go:1391 +0x140
bufio.(*Reader).fill(0xc486f7bc20)
    /usr/local/go/src/bufio/bufio.go:97 +0x11a
bufio.(*Reader).Peek(0xc486f7bc20, 0x1, 0x0, 0x0, 0x0, 0xc4893567e0, 0x0)
    /usr/local/go/src/bufio/bufio.go:129 +0x3a
net/http.(*persistConn).readLoop(0xc486f47b00)
    /usr/local/go/src/net/http/transport.go:1539 +0x185
created by net/http.(*Transport).dialConn
    /usr/local/go/src/net/http/transport.go:1186 +0xa2e

goroutine 6146907 [select]:
net/http.(*persistConn).writeLoop(0xc486f47b00)
    /usr/local/go/src/net/http/transport.go:1759 +0x165
created by net/http.(*Transport).dialConn
    /usr/local/go/src/net/http/transport.go:1187 +0xa53

goroutine 6146903 [select]:
net/http.(*persistConn).writeLoop(0xc486f47c20)
    /usr/local/go/src/net/http/transport.go:1759 +0x165
created by net/http.(*Transport).dialConn
    /usr/local/go/src/net/http/transport.go:1187 +0xa53

goroutine 6146905 [select]:
net/http.(*persistConn).writeLoop(0xc486f479e0)
    /usr/local/go/src/net/http/transport.go:1759 +0x165
created by net/http.(*Transport).dialConn
    /usr/local/go/src/net/http/transport.go:1187 +0xa53

goroutine 6146962 [select]:
github.com/kahing/goofys/internal.(*DirHandle).listObjects(0xc47a538180, 0xc47a52e600, 0x1a, 0x9a0335, 0x1, 0xc47a52e600)
    /home/khc/Code/go/src/github.com/kahing/goofys/internal/dir.go:276 +0x3ed
github.com/kahing/goofys/internal.(*DirHandle).ReadDir(0xc47a538180, 0x2, 0xb, 0xc47a51f140, 0x2)
    /home/khc/Code/go/src/github.com/kahing/goofys/internal/dir.go:363 +0x322
github.com/kahing/goofys/internal.(*Goofys).ReadDir(0xc420172750, 0xc89020, 0xc47a535320, 0xc47a5381c0, 0x0, 0x0)
    /home/khc/Code/go/src/github.com/kahing/goofys/internal/goofys.go:816 +0x260
github.com/jacobsa/fuse/fuseutil.(*fileSystemServer).handleOp(0xc4200c7160, 0xc42013c600, 0xc89020, 0xc47a535320, 0x8ba640, 0xc47a5381c0)
    /home/khc/Code/go/src/github.com/jacobsa/fuse/fuseutil/file_system.go:178 +0xc06
created by github.com/jacobsa/fuse/fuseutil.(*fileSystemServer).ServeOps
    /home/khc/Code/go/src/github.com/jacobsa/fuse/fuseutil/file_system.go:121 +0x176
kahing commented 6 years ago

what were you doing at the time? How much memory was goofys using? How much memory do you have total? Is this reproducible?

kyledayton commented 6 years ago

@kahing I've finally had a chance to gather some data on this. I'm using goofys to mount a directory for vsftp to write files to. Our use case is that we receive files from another service via FTP and have them stored/archived in S3. The machine has 2GB of memory in total.

Have a look at the attached log file, which is the memory/cpu usage of the goofys process captured at 30 second intervals. Memory usage is low for the first 12 hours or so, before spiking considerably to (~1.5g) at 2018-02-21 06:25:35. It then drops down to a little less than 1g at 2018-02-21 06:37:09, and remains that way for the next 24 hours. Finally, right before the process crashed, memory usage spikes rapidly to 1.7g.

memory.zip

kahing commented 6 years ago

I am currently traveling so won't be able to look at this for another week or so.

djmaze commented 3 years ago

@kyledayton It's been a long time, but did you possibly have updatedb running? Excluding the goofys mount in the updatedb config should prevent these regular OOMs. At least it did for me.

Other than that, it looks like this recent commit might fix many of these problems: https://github.com/kahing/goofys/commit/b12cef3a787b50356ca306b7e1947ab91ef0bed7