java - Why is this program which loops many times taking time when there is a `println` after the loops? -
here small code trying. program takes amount of time execute. while running, if try kill through terminate button in eclipse, returns terminate failed. can kill terminal using kill -9 <pid>.
but, when don't print variable result in last line of program (please check commented portion of code), program exits immediately.
i wondering :
why taking time execute when value of result being printed?
please note, if don't printvalue, same loop gets on immediately.why eclipse not able kill program?
update 1 : seems jvm optimize code during runtime (not in compile time). this thread helpful.
update 2 : when print value of value, jstack <pid> not working. jstack -f <pid> working. possible reason?
public class testclient { private static void loop() { long value =0; (int j = 0; j < 50000; j++) { (int = 0; < 100000000; i++) { value += 1; } } //when value being printed, program //is taking time complete system.out.println("done "+ value); //when value not being printed, program //completes //system.out.println("done "); } public static void main(string[] args) { loop(); } }
this jit compiler optimization (not java compiler optimization).
if compare byte code generated java compiler 2 versions see loop present in both of them.
this how decompiled method println looks:
private static void loop() { long value = 0l; for(int j = 0; j < '썐'; ++j) { for(int = 0; < 100000000; ++i) { ++value; } } system.out.println("done " + value); } this how decompiled method looks when println removed:
private static void loop() { long value = 0l; for(int j = 0; j < '썐'; ++j) { for(int = 0; < 100000000; ++i) { ++value; } } } as can see loops still there.
however can enable jit compiler logging , assembly printing following jvm options:
-xx:+unlockdiagnosticvmoptions -xx:+logcompilation -xx:+printassembly you may need download hsdis-amd64.dylib , put in working directory (macos, hotspot java 8)
after run testclient should see code produced jit compiler in console. here post excerpt output.
version without println:
# {method} 'loop' '()v' in 'test/testclient' 0x000000010e3c2500: callq 0x000000010dc1c202 ; {runtime_call} 0x000000010e3c2505: data32 data32 nopw 0x0(%rax,%rax,1) 0x000000010e3c2510: sub $0x18,%rsp 0x000000010e3c2517: mov %rbp,0x10(%rsp) 0x000000010e3c251c: mov %rsi,%rdi 0x000000010e3c251f: movabs $0x10dc760ec,%r10 0x000000010e3c2529: callq *%r10 ;*iload_3 ; - test.testclient::loop@12 (line 9) 0x000000010e3c252c: add $0x10,%rsp 0x000000010e3c2530: pop %rbp 0x000000010e3c2531: test %eax,-0x1c18537(%rip) # 0x000000010c7aa000 ; {poll_return} 0x000000010e3c2537: retq version println:
# {method} 'loop' '()v' in 'test/testclient' 0x00000001092c36c0: callq 0x0000000108c1c202 ; {runtime_call} 0x00000001092c36c5: data32 data32 nopw 0x0(%rax,%rax,1) 0x00000001092c36d0: mov %eax,-0x14000(%rsp) 0x00000001092c36d7: push %rbp 0x00000001092c36d8: sub $0x10,%rsp 0x00000001092c36dc: mov 0x10(%rsi),%r13 0x00000001092c36e0: mov 0x8(%rsi),%ebp 0x00000001092c36e3: mov (%rsi),%ebx 0x00000001092c36e5: mov %rsi,%rdi 0x00000001092c36e8: movabs $0x108c760ec,%r10 0x00000001092c36f2: callq *%r10 0x00000001092c36f5: jmp 0x00000001092c3740 0x00000001092c36f7: add $0x1,%r13 ;*iload_3 ; - test.testclient::loop@12 (line 9) 0x00000001092c36fb: inc %ebx ;*iinc ; - test.testclient::loop@22 (line 9) 0x00000001092c36fd: cmp $0x5f5e101,%ebx 0x00000001092c3703: jl 0x00000001092c36f7 ;*if_icmpge ; - test.testclient::loop@15 (line 9) 0x00000001092c3705: jmp 0x00000001092c3734 0x00000001092c3707: nopw 0x0(%rax,%rax,1) 0x00000001092c3710: mov %r13,%r8 ;*iload_3 ; - test.testclient::loop@12 (line 9) 0x00000001092c3713: mov %r8,%r13 0x00000001092c3716: add $0x10,%r13 ;*ladd ; - test.testclient::loop@20 (line 10) 0x00000001092c371a: add $0x10,%ebx ;*iinc ; - test.testclient::loop@22 (line 9) 0x00000001092c371d: cmp $0x5f5e0f2,%ebx 0x00000001092c3723: jl 0x00000001092c3710 ;*if_icmpge ; - test.testclient::loop@15 (line 9) 0x00000001092c3725: add $0xf,%r8 ;*ladd ; - test.testclient::loop@20 (line 10) 0x00000001092c3729: cmp $0x5f5e101,%ebx 0x00000001092c372f: jl 0x00000001092c36fb 0x00000001092c3731: mov %r8,%r13 ;*iload_3 ; - test.testclient::loop@12 (line 9) 0x00000001092c3734: inc %ebp ;*iinc ; - test.testclient::loop@28 (line 8) 0x00000001092c3736: cmp $0xc350,%ebp 0x00000001092c373c: jge 0x00000001092c376c ;*if_icmpge ; - test.testclient::loop@7 (line 8) 0x00000001092c373e: xor %ebx,%ebx 0x00000001092c3740: mov %ebx,%r11d 0x00000001092c3743: inc %r11d ;*iload_3 ; - test.testclient::loop@12 (line 9) 0x00000001092c3746: mov %r13,%r8 0x00000001092c3749: add $0x1,%r8 ;*ladd ; - test.testclient::loop@20 (line 10) 0x00000001092c374d: inc %ebx ;*iinc ; - test.testclient::loop@22 (line 9) 0x00000001092c374f: cmp %r11d,%ebx 0x00000001092c3752: jge 0x00000001092c3759 ;*if_icmpge ; - test.testclient::loop@15 (line 9) 0x00000001092c3754: mov %r8,%r13 0x00000001092c3757: jmp 0x00000001092c3746 0x00000001092c3759: cmp $0x5f5e0f2,%ebx 0x00000001092c375f: jl 0x00000001092c3713 0x00000001092c3761: mov %r13,%r10 0x00000001092c3764: mov %r8,%r13 0x00000001092c3767: mov %r10,%r8 0x00000001092c376a: jmp 0x00000001092c3729 ;*if_icmpge ; - test.testclient::loop@7 (line 8) 0x00000001092c376c: mov $0x24,%esi 0x00000001092c3771: mov %r13,%rbp 0x00000001092c3774: data32 xchg %ax,%ax 0x00000001092c3777: callq 0x0000000109298f20 ; oopmap{off=188} ;*getstatic out ; - test.testclient::loop@34 (line 13) ; {runtime_call} 0x00000001092c377c: callq 0x0000000108c1c202 ;*getstatic out ; - test.testclient::loop@34 (line 13) ; {runtime_call} also should have hotspot.log file jit compiler steps. here excerpt:
<phase name='optimizer' nodes='114' live='77' stamp='0.100'> <phase name='idealloop' nodes='115' live='67' stamp='0.100'> <loop_tree> <loop idx='119' > <loop idx='185' main_loop='185' > </loop> </loop> </loop_tree> <phase_done name='idealloop' nodes='197' live='111' stamp='0.101'/> </phase> <phase name='idealloop' nodes='197' live='111' stamp='0.101'> <loop_tree> <loop idx='202' > <loop idx='159' inner_loop='1' pre_loop='131' > </loop> <loop idx='210' inner_loop='1' main_loop='210' > </loop> <loop idx='138' inner_loop='1' post_loop='131' > </loop> </loop> </loop_tree> <phase_done name='idealloop' nodes='221' live='113' stamp='0.101'/> </phase> <phase name='idealloop' nodes='221' live='113' stamp='0.101'> <loop_tree> <loop idx='202' > <loop idx='159' inner_loop='1' pre_loop='131' > </loop> <loop idx='210' inner_loop='1' main_loop='210' > </loop> <loop idx='138' inner_loop='1' post_loop='131' > </loop> </loop> </loop_tree> <phase_done name='idealloop' nodes='241' live='63' stamp='0.101'/> </phase> <phase name='ccp' nodes='241' live='63' stamp='0.101'> <phase_done name='ccp' nodes='241' live='63' stamp='0.101'/> </phase> <phase name='idealloop' nodes='241' live='63' stamp='0.101'> <loop_tree> <loop idx='202' inner_loop='1' > </loop> </loop_tree> <phase_done name='idealloop' nodes='253' live='56' stamp='0.101'/> </phase> <phase name='idealloop' nodes='253' live='56' stamp='0.101'> <phase_done name='idealloop' nodes='253' live='33' stamp='0.101'/> </phase> <phase_done name='optimizer' nodes='253' live='33' stamp='0.101'/> </phase> you can further analyze hotspot.log file produced jit compiler using jitwatch tool https://github.com/adoptopenjdk/jitwatch/wiki
to disable jit compiler , run java virtual machine in all-interpreted mode can use -djava.compiler=none jvm option.
a similar question in post why jvm doing runtime loop optimization , making code buggy?
Comments
Post a Comment