#908082 eatmydata is incompatible with tcmalloc

Package:
eatmydata
Source:
libeatmydata
Submitter:
Santiago Vila
Date:
2018-12-11 10:30:10 UTC
Severity:
wishlist
#908082#5
Date:
2018-09-05 23:05:28 UTC
From:
To:
Dear maintainer:

When I build this package using sbuild + eatmydata this is what happens:
--------------------------------------------------------------------------------
[...]
 debian/rules build-indep
dh build-indep --buildsystem=golang --with=golang
   dh_update_autotools_config -i -O--buildsystem=golang
   dh_autoreconf -i -O--buildsystem=golang
   dh_auto_configure -i -O--buildsystem=golang
   dh_auto_build -i -O--buildsystem=golang
	cd obj-x86_64-linux-gnu && go install -gcflags=\"-trimpath=/<<BUILDDIR>>/golang-github-juju-testing-0.0\~git20170608.2fe0e88/obj-x86_64-linux-gnu/src\" -asmflags=\"-trimpath=/<<BUILDDIR>>/golang-github-juju-testing-0.0\~git20170608.2fe0e88/obj-x86_64-linux-gnu/src\" -v -p 1 github.com/juju/testing github.com/juju/testing/checkers github.com/juju/testing/filetesting github.com/juju/testing/httptesting
github.com/juju/errors
github.com/juju/loggo
github.com/juju/retry
gopkg.in/check.v1
gopkg.in/mgo.v2/internal/json
gopkg.in/mgo.v2/bson
gopkg.in/yaml.v2
github.com/juju/testing/checkers
github.com/juju/utils/clock
golang.org/x/crypto/pbkdf2
golang.org/x/net/context
github.com/juju/utils
github.com/juju/version
gopkg.in/mgo.v2/internal/scram
gopkg.in/mgo.v2
github.com/juju/testing
github.com/juju/testing/filetesting
github.com/juju/testing/httptesting
   dh_auto_test -i -O--buildsystem=golang
	cd obj-x86_64-linux-gnu && go test -vet=off -v -p 1 github.com/juju/testing github.com/juju/testing/checkers github.com/juju/testing/filetesting github.com/juju/testing/httptesting
=== RUN   Test
SIGQUIT: quit
PC=0x472298 m=0 sigcode=0

goroutine 6 [syscall]:
syscall.Syscall6(0xf7, 0x1, 0x7d43, 0xc420069600, 0x1000004, 0x0, 0x0, 0x0, 0xbafe20, 0x0)
	/usr/lib/go-1.10/src/syscall/asm_linux_amd64.s:44 +0x5 fp=0xc4200695a8 sp=0xc4200695a0 pc=0x472275
os.(*Process).blockUntilWaitable(0xc420026780, 0x0, 0x0, 0x2)
	/usr/lib/go-1.10/src/os/wait_waitid.go:31 +0x98 fp=0xc4200696a8 sp=0xc4200695a8 pc=0x493668
os.(*Process).wait(0xc420026780, 0xc4200feb60, 0xc4200ce4f8, 0xc4200ce4f8)
	/usr/lib/go-1.10/src/os/exec_unix.go:22 +0x3c fp=0xc420069720 sp=0xc4200696a8 pc=0x48d5ac
os.(*Process).Wait(0xc420026780, 0x936048, 0x936050, 0x936040)
	/usr/lib/go-1.10/src/os/exec.go:123 +0x2b fp=0xc420069750 sp=0xc420069720 pc=0x48cb5b
os/exec.(*Cmd).Wait(0xc4200ce420, 0x0, 0x0)
	/usr/lib/go-1.10/src/os/exec/exec.go:461 +0x5c fp=0xc4200697c8 sp=0xc420069750 pc=0x53cc8c
os/exec.(*Cmd).Run(0xc4200ce420, 0xc420088910, 0x1)
	/usr/lib/go-1.10/src/os/exec/exec.go:305 +0x5c fp=0xc4200697f0 sp=0xc4200697c8 pc=0x53c16c
os/exec.(*Cmd).Output(0xc4200ce420, 0xf, 0xc4200578b8, 0x1, 0x1, 0xc4200ce420)
	/usr/lib/go-1.10/src/os/exec/exec.go:500 +0xf5 fp=0xc420069840 sp=0xc4200697f0 pc=0x53d085
github.com/juju/testing.detectMongoVersion(0xc420154b40, 0xf, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc420057cb0, 0xe0)
	/<<PKGBUILDDIR>>/obj-x86_64-linux-gnu/src/github.com/juju/testing/mgo.go:396 +0xb0 fp=0xc4200699b8 sp=0xc420069840 pc=0x7f0e90
github.com/juju/testing.(*mongodCache).Get(0xbaf180, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/<<PKGBUILDDIR>>/obj-x86_64-linux-gnu/src/github.com/juju/testing/mgo.go:359 +0x170 fp=0xc420069a58 sp=0xc4200699b8 pc=0x7f0830
github.com/juju/testing.(*MgoInstance).run(0xbaf300, 0xc, 0xc420057e78)
	/<<PKGBUILDDIR>>/obj-x86_64-linux-gnu/src/github.com/juju/testing/mgo.go:260 +0x1a8 fp=0xc420069da0 sp=0xc420069a58 pc=0x7ef848
github.com/juju/testing.(*MgoInstance).Start(0xbaf300, 0x0, 0x17f7a0e4, 0x17f7a0e400a2d078)
	/<<PKGBUILDDIR>>/obj-x86_64-linux-gnu/src/github.com/juju/testing/mgo.go:206 +0x38f fp=0xc420069f48 sp=0xc420069da0 pc=0x7ef1bf
github.com/juju/testing.MgoTestPackage(0xc4201660f0, 0x0)
	/<<PKGBUILDDIR>>/obj-x86_64-linux-gnu/src/github.com/juju/testing/mgo.go:455 +0x3b fp=0xc420069f88 sp=0xc420069f48 pc=0x7f186b
github.com/juju/testing_test.Test(0xc4201660f0)
	/<<PKGBUILDDIR>>/obj-x86_64-linux-gnu/src/github.com/juju/testing/package_test.go:13 +0x34 fp=0xc420069fa8 sp=0xc420069f88 pc=0x805d34
testing.tRunner(0xc4201660f0, 0x935870)
	/usr/lib/go-1.10/src/testing/testing.go:777 +0xd0 fp=0xc420069fd0 sp=0xc420069fa8 pc=0x4ed330
runtime.goexit()
	/usr/lib/go-1.10/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc420069fd8 sp=0xc420069fd0 pc=0x45b471
created by testing.(*T).Run
	/usr/lib/go-1.10/src/testing/testing.go:824 +0x2e0

goroutine 1 [chan receive]:
testing.(*T).Run(0xc4201660f0, 0x917136, 0x4, 0x935870, 0x47e966)
	/usr/lib/go-1.10/src/testing/testing.go:825 +0x301
testing.runTests.func1(0xc420166000)
	/usr/lib/go-1.10/src/testing/testing.go:1063 +0x64
testing.tRunner(0xc420166000, 0xc42013fdf8)
	/usr/lib/go-1.10/src/testing/testing.go:777 +0xd0
testing.runTests(0xc4200feb00, 0xba18a0, 0x1, 0x1, 0x411eb9)
	/usr/lib/go-1.10/src/testing/testing.go:1061 +0x2c4
testing.(*M).Run(0xc420118800, 0x0)
	/usr/lib/go-1.10/src/testing/testing.go:978 +0x171
main.main()
	_testmain.go:44 +0x151

goroutine 7 [IO wait]:
internal/poll.runtime_pollWait(0x7f32ba14af00, 0x72, 0xc4200464e8)
	/usr/lib/go-1.10/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc4200889c8, 0x72, 0xffffffffffffff01, 0x9729c0, 0xb73650)
	/usr/lib/go-1.10/src/internal/poll/fd_poll_runtime.go:85 +0x9b
internal/poll.(*pollDesc).waitRead(0xc4200889c8, 0xc420122401, 0x200, 0x200)
	/usr/lib/go-1.10/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc4200889b0, 0xc420122400, 0x200, 0x200, 0x0, 0x0, 0x0)
	/usr/lib/go-1.10/src/internal/poll/fd_unix.go:157 +0x17d
os.(*File).read(0xc42000e0f8, 0xc420122400, 0x200, 0x200, 0xc420122400, 0x0, 0x0)
	/usr/lib/go-1.10/src/os/file_unix.go:226 +0x4e
os.(*File).Read(0xc42000e0f8, 0xc420122400, 0x200, 0x200, 0x4ed28d, 0xa2d078, 0xc420046660)
	/usr/lib/go-1.10/src/os/file.go:107 +0x6a
bytes.(*Buffer).ReadFrom(0xc42016a000, 0x971da0, 0xc42000e0f8, 0x7f32ba14f040, 0xc42016a000, 0x1)
	/usr/lib/go-1.10/src/bytes/buffer.go:205 +0xa0
io.copyBuffer(0x971260, 0xc42016a000, 0x971da0, 0xc42000e0f8, 0x0, 0x0, 0x0, 0x4ed28d, 0xc420001980, 0xc42006d4c0)
	/usr/lib/go-1.10/src/io/io.go:386 +0x31a
io.Copy(0x971260, 0xc42016a000, 0x971da0, 0xc42000e0f8, 0x17f7a0e400a2d078, 0x5b84d612, 0xc420046798)
	/usr/lib/go-1.10/src/io/io.go:362 +0x5a
os/exec.(*Cmd).writerDescriptor.func1(0x4ed330, 0xc4201660f0)
	/usr/lib/go-1.10/src/os/exec/exec.go:275 +0x4d
os/exec.(*Cmd).Start.func1(0xc4200ce420, 0xc4200feba0)
	/usr/lib/go-1.10/src/os/exec/exec.go:396 +0x27
created by os/exec.(*Cmd).Start
	/usr/lib/go-1.10/src/os/exec/exec.go:395 +0x5df

goroutine 8 [IO wait]:
internal/poll.runtime_pollWait(0x7f32ba14ad60, 0x72, 0xc420046d58)
	/usr/lib/go-1.10/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc420088a68, 0x72, 0xffffffffffffff01, 0x9729c0, 0xb73650)
	/usr/lib/go-1.10/src/internal/poll/fd_poll_runtime.go:85 +0x9b
internal/poll.(*pollDesc).waitRead(0xc420088a68, 0xc42016e001, 0x8000, 0x8000)
	/usr/lib/go-1.10/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc420088a50, 0xc42016e000, 0x8000, 0x8000, 0x0, 0x0, 0x0)
	/usr/lib/go-1.10/src/internal/poll/fd_unix.go:157 +0x17d
os.(*File).read(0xc42000e110, 0xc42016e000, 0x8000, 0x8000, 0x0, 0x0, 0xc420046e60)
	/usr/lib/go-1.10/src/os/file_unix.go:226 +0x4e
os.(*File).Read(0xc42000e110, 0xc42016e000, 0x8000, 0x8000, 0x8000, 0x8000, 0x0)
	/usr/lib/go-1.10/src/os/file.go:107 +0x6a
io.copyBuffer(0x971ea0, 0xc420088910, 0x971da0, 0xc42000e110, 0xc42016e000, 0x8000, 0x8000, 0x0, 0x0, 0x0)
	/usr/lib/go-1.10/src/io/io.go:400 +0x164
io.Copy(0x971ea0, 0xc420088910, 0x971da0, 0xc42000e110, 0x0, 0x0, 0x0)
	/usr/lib/go-1.10/src/io/io.go:362 +0x5a
os/exec.(*Cmd).writerDescriptor.func1(0x0, 0x0)
	/usr/lib/go-1.10/src/os/exec/exec.go:275 +0x4d
os/exec.(*Cmd).Start.func1(0xc4200ce420, 0xc4200febe0)
	/usr/lib/go-1.10/src/os/exec/exec.go:396 +0x27
created by os/exec.(*Cmd).Start
	/usr/lib/go-1.10/src/os/exec/exec.go:395 +0x5df

rax    0xf7
rbx    0x0
rcx    0x47229a
rdx    0xc420069600
rdi    0x1
rsi    0x7d43
rbp    0xc420069698
rsp    0xc4200695a0
r8     0x0
r9     0x0
r10    0x1000004
r11    0x202
r12    0x1ffffffffffffff
r13    0xff
r14    0xff
r15    0x29
rip    0x472298
rflags 0x202
cs     0x33
fs     0x0
gs     0x0
*** Test killed with quit: ran too long (10m0s).
FAIL	github.com/juju/testing	600.005s
=== RUN   Test
OK: 47 passed, 5 skipped
--- PASS: Test (0.00s)
=== RUN   TestDeepEqual
--- PASS: TestDeepEqual (0.00s)
=== RUN   TestDeepEqualRecursiveStruct
--- PASS: TestDeepEqualRecursiveStruct (0.00s)
=== RUN   TestDeepEqualComplexStruct
--- PASS: TestDeepEqualComplexStruct (0.00s)
=== RUN   TestDeepEqualComplexStructInequality
--- PASS: TestDeepEqualComplexStructInequality (0.00s)
=== RUN   TestDeepEqualUnexportedMap
--- PASS: TestDeepEqualUnexportedMap (0.00s)
PASS
ok  	github.com/juju/testing/checkers	0.007s
=== RUN   Test
OK: 15 passed, 22 expected failures
--- PASS: Test (0.03s)
PASS
ok  	github.com/juju/testing/filetesting	0.037s
=== RUN   Test
OK: 5 passed
--- PASS: Test (0.00s)
PASS
ok  	github.com/juju/testing/httptesting	0.007s
dh_auto_test: cd obj-x86_64-linux-gnu && go test -vet=off -v -p 1 github.com/juju/testing github.com/juju/testing/checkers github.com/juju/testing/filetesting github.com/juju/testing/httptesting returned exit code 1
make: *** [debian/rules:4: build-indep] Error 1
dpkg-buildpackage: error: debian/rules build-indep subprocess returned exit status 2
--------------------------------------------------------------------------------

I've put a bunch of build logs here, but they are similar:

https://people.debian.org/~sanvila/build-logs/golang-github-juju-testing/

I know there is not a policy anywhere saying that packages should build with eatmydata,
but it's something that makes the build a lot faster and when a package does not build
that way I have to special case it.

My building environment is described here:

https://people.debian.org/~sanvila/my-building-environment.txt

by I guess a simple "eatmydata dpkg-buildpackage" would also work.

Thanks.
#908082#10
Date:
2018-09-06 07:24:36 UTC
From:
To:
This is not a bug with this package, but with mongodb-server:

root@gce1535991:~# mongod --version
db version v3.4.15
git version: 52e5b5fbaa3a2a5b1a217f5e647b5061817475f9
OpenSSL version: OpenSSL 1.1.0f  25 May 2017
allocator: tcmalloc
modules: none
build environment:
    distarch: x86_64
    target_arch: x86_64
root@gce1535991:~# eatmydata mongod --version
^C

This package uses mongodb in its tests, hence the hang.

I’ll leave it up to you to merge and reassign accordingly.
#908082#27
Date:
2018-12-11 10:19:47 UTC
From:
To:
Hi,

It looks like this is an incompatibility between eatmydata and tcmalloc:

(gdb) bt
#0  0x00007f4e24cf9c41 in __GI___nanosleep (requested_time=0x7ffcaa6523e0,
    remaining=0x0) at ../sysdeps/unix/sysv/linux/nanosleep.c:28
#1  0x00007f4e25d08753 in base::internal::SpinLockDelay(int volatile*, int, int)
    () from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#2  0x00007f4e25d08623 in SpinLock::SlowLock() ()
   from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#3  0x00007f4e25cfcf54 in tcmalloc::ThreadCache::InitModule() ()
   from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#4  0x00007f4e25cfd06d in tcmalloc::ThreadCache::CreateCacheIfNecessary() ()
   from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#5  0x00007f4e25d0b20a in tc_calloc ()
   from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#6  0x00007f4e2503ba25 in _dlerror_run (
    operate=operate@entry=0x7f4e2503b3b0 <dlsym_doit>,
    args=args@entry=0x7ffcaa652500) at dlerror.c:140
#7  0x00007f4e2503b42f in __dlsym (handle=handle@entry=0xffffffffffffffff,
    name=name@entry=0x7f4e26144000 "open") at dlsym.c:70
#8  0x00007f4e261430b1 in eatmydata_init () at libeatmydata/libeatmydata.c:80
#9  0x00007f4e261434a5 in eatmydata_is_hungry () at libeatmydata/libeatmydata.c:96
#10 msync (addr=<optimized out>, length=<optimized out>, flags=<optimized out>)
    at libeatmydata/libeatmydata.c:204
#11 0x00007f4e24911fc4 in ?? () from /usr/lib/x86_64-linux-gnu/libunwind.so.8
#12 0x00007f4e24915d21 in ?? () from /usr/lib/x86_64-linux-gnu/libunwind.so.8
#13 0x00007f4e2491601f in ?? () from /usr/lib/x86_64-linux-gnu/libunwind.so.8
#14 0x00007f4e24916569 in ?? () from /usr/lib/x86_64-linux-gnu/libunwind.so.8
#15 0x00007f4e24912ac1 in _ULx86_64_step ()
   from /usr/lib/x86_64-linux-gnu/libunwind.so.8
#16 0x00007f4e25d0905b in ?? () from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#17 0x00007f4e25d09634 in GetStackTrace(void**, int, int) ()
   from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#18 0x00007f4e25cfa6a6 in tcmalloc::PageHeap::GrowHeap(unsigned long) ()
   from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#19 0x00007f4e25cfa93b in tcmalloc::PageHeap::New(unsigned long) ()
   from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#20 0x00007f4e25cf8865 in tcmalloc::CentralFreeList::Populate() ()
   from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#21 0x00007f4e25cf8a68 in tcmalloc::CentralFreeList::FetchFromOneSpansSafe(int, void**, void**) () from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#22 0x00007f4e25cf8b67 in tcmalloc::CentralFreeList::RemoveRange(void**, void**, int) () from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#23 0x00007f4e25cfc3a0 in tcmalloc::ThreadCache::FetchFromCentralCache(unsigned int, int, void* (*)(unsigned long)) ()
   from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#24 0x00007f4e25d0c775 in tcmalloc::allocate_full_malloc_oom(unsigned long) ()
   from /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4
#25 0x00007f4e24f46416 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#26 0x00007f4e261af0ca in call_init (l=<optimized out>, argc=argc@entry=2,
    argv=argv@entry=0x7ffcaa6535e8, env=env@entry=0x7ffcaa653600) at dl-init.c:72
#27 0x00007f4e261af1d6 in call_init (env=0x7ffcaa653600, argv=0x7ffcaa6535e8,
    argc=2, l=<optimized out>) at dl-init.c:118
#28 _dl_init (main_map=0x7f4e261c9170, argc=2, argv=0x7ffcaa6535e8,
    env=0x7ffcaa653600) at dl-init.c:119
#29 0x00007f4e261a124a in _dl_start_user () from /lib64/ld-linux-x86-64.so.2

Without digging too deep, AFAICT eatmydata is injected in tcmalloc's
initialization path (#24) through msync (#10), which in turn tries to
calloc() more memory, causing a deadlock. I'm reassigning this to
eatmydata, since I guess it should be as transparent as possible and not
interfere with the underlying memory allocator used.

Regards,
Apollon