CODEWITHSUNDEEP
performancegroovyredhat
Roman Goyenko
Roman Goyenko

Reputation: 7070

Groovy startup very slow

I have a problem when I start Groovy on one of my Linux machines - it takes about 30 seconds to execute very simple command:

groovy -e ""

if I run strace on it, here is what I see where it stops and waits:

mprotect(0x7fae284e0000, 4096, PROT_NONE) = 0
clone(child_stack=0x7fae285dfff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fae285e09d0, tls=0x7fae285e0700, child_tidptr=0x7fae285e09d0) = 62660
futex(0x7fae285e09d0, FUTEX_WAIT, 62660, NULL <unfinished ...>

Is there a way to figure out what it's waiting for and why and how to fix it?

I am running Red Hat 6.3, Groovy Version: 2.2.1 JVM: 1.7.0_25 Vendor: Oracle Corporation OS: Linux

and here is time command:

bin$ time groovy -e ""

real 0m22.255s user 0m26.875s sys 0m2.064s

EDITED:

as per the suggestion, did strace -f, here is what I see: 

[pid 49451] <... gettimeofday resumed> {1397076179, 998954}, NULL) = 0
[pid 49482] clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
[pid 49451] gettimeofday( <unfinished ...>
[pid 49482] <... clock_gettime resumed> {10719052, 15135866}) = 0
[pid 49451] <... gettimeofday resumed> {1397076180, 871}, NULL) = 0
[pid 49482] gettimeofday({1397076180, 2272}, NULL) = 0
[pid 49451] gettimeofday( <unfinished ...>
[pid 49482] futex(0x7fde3c145554, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1, {1397076180, 52272000}, ffffffff <unfinished ...>
[pid 49451] <... gettimeofday resumed> {1397076180, 3226}, NULL) = 0
[pid 49451] gettimeofday({1397076180, 5444}, NULL) = 0
[pid 49451] gettimeofday({1397076180, 7123}, NULL) = 0
[pid 49451] gettimeofday({1397076180, 8765}, NULL) = 0
[pid 49451] gettimeofday({1397076180, 9766}, NULL) = 0
[pid 49451] gettimeofday({1397076180, 10650}, NULL) = 0
[pid 49451] gettimeofday({1397076180, 11611}, NULL) = 0
[pid 49451] gettimeofday({1397076180, 12648}, NULL) = 0
[pid 49451] gettimeofday({1397076180, 13569}, NULL) = 0
[pid 49451] gettimeofday({1397076180, 14450}, NULL) = 0
[pid 49451] gettimeofday({1397076180, 16851}, NULL) = 0
[pid 49451] gettimeofday({1397076180, 17891}, NULL) = 0
[pid 49451] gettimeofday({1397076180, 19012}, NULL) = 0
[pid 49451] gettimeofday({1397076180, 20415}, NULL) = 0
[pid 49451] gettimeofday({1397076180, 21734}, NULL) = 0

looks like it's waiting for gettimeofday, I see a lot of this in the trace.

and here is how it ends: 

[pid 49475] gettimeofday({1397076182, 86016}, NULL) = 0
[pid 49475] futex(0x7fde3c008754, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7fde3c008750, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
[pid 49451] <... futex resumed> )       = 0
[pid 49475] madvise(0x7fddf09d6000, 1028096, MADV_DONTNEED <unfinished ...>
[pid 49451] futex(0x7fde3c008728, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 49475] <... madvise resumed> )     = 0
[pid 49451] <... futex resumed> )       = 0
[pid 49475] _exit(0)                    = ?
Process 49475 detached
[pid 49451] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid 49451] unlink("/tmp/mydirectory/49439") = 0
[pid 49451] madvise(0x7fde42dcc000, 1028096, MADV_DONTNEED) = 0
[pid 49451] _exit(0)                    = ?
Process 49451 detached
[pid 49439] <... futex resumed> )       = 0
[pid 49439] exit_group(0)               = ?

Upvotes: 2

Views: 1337

Answers (1)

Dror Bereznitsky
Dror Bereznitsky

Reputation: 20376

The large number of gettimeofday calls to might be related to this bug report.
You can try the suggested workaround and start Groovy with the -XX:-UsePerfData JVM option.
If it will not help reducing the startup time, at least it will clear the strace output and may help getting better information from it.

Upvotes: 1

Related Questions