Thomas Gard

Ranch Hand
+ Follow
since Nov 24, 2014
Cows and Likes
Cows
Total received
2
In last 30 days
0
Total given
0
Likes
Total received
8
Received in last 30 days
2
Total given
8
Given in last 30 days
0
Forums and Threads
Scavenger Hunt
(keep public parts private until JForum day)
expand Ranch Hand Scavenger Hunt
expand Greenhorn Scavenger Hunt
Moderation Tools

Recent posts by Thomas Gard


Opinion:

Among the problems I'm facing with the various introductions to Function Programming is that precisely what it is so often centers around:

1. You can do this! (With example that supposedly saves time).
2. You can say what you want done, not how to do it.  (A clumsy attempt at declarative definitions IMO because "what you want done" requires the imperative of how to do it).

...when before all of that there should be the emphasis on this:

1. You focus on the removing of state.

It took just one posting from Robert C. Martin, (AKA "Uncle Bob"), for me to realize this, and prior to that the benefits to avoiding state were taking a distinct back seat.

In his various follow up articles he pointed out quite simply:

1. The speed of light, and hence slightly lesser speed of electron propagation, is finally truly the limiting problem in classic CPU design speed.  This is why the curve of ever increasing clock speeds has flatlined.
2. We can't easily shrink things either to gain speed any longer because the conduit widths are already measured in numbers of atoms.
3. Currently, the only thing truly on the horizon (and no, I agree with him that Quantum computing is still not close to being proven as real, despite the flurry of articles that mistakenly state what the qubit is doing), is to add cores.
3. Java engineer teams can barely manage getting two threads to cooperate when there is state change involved, even with help from concurrent facilities.
4. And then he asked an important question: Are you ready for 32 cores?  1024 cores?  65536 cores?

This brought me right back to my early exposure to Lisp where there were no loop constructs other than recursive calls, and the reason behind it all just clicked.  I had a model that makes sense.

So now I'm in this far more comfortable learning position (for me): FP is a win not because you can now do this instead of that and make it less wordy code (the opening descriptions from one page after another).  It's a win because your focus is on avoiding state, and by avoiding state you can avoid all the pitfalls of state, the primary one being that you can't easily scale horizontally to multiple threads/cores.

Starting from there, I can now finally see the wisdom in the Lambda expressions emphasis in Java 8, and have something to focus on.






Apparently the problem goes away with the JVM option "-XX:+UseCountedLoopSafepoints" when used on a JDK greater than or equal to JDK1.8.0_92 (current for 8 is _161).

I don't know if that option exists in later JVMs.
2 weeks ago

(Perhaps this is easier to read outside of code blocks)


RUNTIME RESULTS WITH PAUSES
When MAKE_THE_JVM_PAUSE_UNEXPECTEDLY is true, these are the pauses (see between heartbeat 49 and 50 for the first occurrence):


[GC (Allocation Failure) [PSYoungGen: 512K->352K(1024K)] 512K->352K(523776K), 0.0005131 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.045: ParallelGCFailedAllocation       [       5          0              0    ]      [     0     0     0     0     0    ]  0  
Total time for which application threads were stopped: 0.0006108 seconds
[GC (Allocation Failure) [PSYoungGen: 864K->480K(1536K)] 864K->504K(524288K), 0.0004007 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.056: ParallelGCFailedAllocation       [       5          0              0    ]      [     0     0     0     0     0    ]  0  
Total time for which application threads were stopped: 0.0004828 seconds
[GC (Allocation Failure) [PSYoungGen: 1504K->480K(1536K)] 1528K->664K(524288K), 0.0015536 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.076: ParallelGCFailedAllocation       [      10          0              0    ]      [     0     0     0     0     1    ]  0  
Total time for which application threads were stopped: 0.0016443 seconds
[GC (Allocation Failure) [PSYoungGen: 1500K->512K(2560K)] 1684K->1008K(525312K), 0.0006902 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.093: ParallelGCFailedAllocation       [      11          1              0    ]      [     1     0     1     0     0    ]  0  
Total time for which application threads were stopped: 0.0023858 seconds
[GC (Allocation Failure) [PSYoungGen: 2556K->499K(2560K)] 3053K->2967K(525312K), 0.0016386 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.096: ParallelGCFailedAllocation       [      11          0              1    ]      [     0     0     0     0     1    ]  0  
Total time for which application threads were stopped: 0.0017466 seconds
[GC (Allocation Failure) [PSYoungGen: 2544K->2547K(6144K)] 5012K->5158K(528896K), 0.0019575 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.098: ParallelGCFailedAllocation       [      11          0              1    ]      [     0     0     0     0     2    ]  0  
Total time for which application threads were stopped: 0.0020448 seconds
[GC (Allocation Failure) [PSYoungGen: 6128K->3059K(6656K)] 8738K->8759K(529408K), 0.0025565 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.100: ParallelGCFailedAllocation       [      11          0              0    ]      [     0     0     0     0     2    ]  0  
Total time for which application threads were stopped: 0.0026380 seconds
[GC (Allocation Failure) [PSYoungGen: 6643K->5632K(11264K)] 12343K->12551K(534016K), 0.0029756 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.103: ParallelGCFailedAllocation       [      11          0              1    ]      [     0     0     0     0     3    ]  0  
Total time for which application threads were stopped: 0.0030744 seconds
[GC (Allocation Failure) [PSYoungGen: 11264K->7168K(12800K)] 18183K->18239K(535552K), 0.0022057 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.107: ParallelGCFailedAllocation       [      11          0              1    ]      [     0     0     0     0     2    ]  0  
Total time for which application threads were stopped: 0.0022910 seconds
[GC (Allocation Failure) [PSYoungGen: 12800K->9408K(17920K)] 23871K->24066K(540672K), 0.0037846 secs] [Times: user=0.01 sys=0.03, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.110: ParallelGCFailedAllocation       [      11          0              1    ]      [     0     0     0     0     3    ]  0  
Total time for which application threads were stopped: 0.0038756 seconds
0-->Delta time from Start[0ms], from last[0ms]
1-->Delta time from Start[218ms], from last[218ms]
2-->Delta time from Start[418ms], from last[200ms]
3-->Delta time from Start[618ms], from last[200ms]
4-->Delta time from Start[818ms], from last[200ms]
5-->Delta time from Start[1018ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
1.114: no vm operation                  [      11          2              2    ]      [     0     0     0     0     0    ]  2  
Total time for which application threads were stopped: 0.0000978 seconds
6-->Delta time from Start[1218ms], from last[200ms]
7-->Delta time from Start[1418ms], from last[200ms]
8-->Delta time from Start[1618ms], from last[200ms]
9-->Delta time from Start[1818ms], from last[200ms]
10-->Delta time from Start[2018ms], from last[200ms]
11-->Delta time from Start[2218ms], from last[200ms]
12-->Delta time from Start[2418ms], from last[200ms]
13-->Delta time from Start[2618ms], from last[200ms]
14-->Delta time from Start[2818ms], from last[200ms]
15-->Delta time from Start[3018ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
3.114: no vm operation                  [      11          2              2    ]      [     0     0     0     0     0    ]  2  
Total time for which application threads were stopped: 0.0000632 seconds
16-->Delta time from Start[3218ms], from last[200ms]
17-->Delta time from Start[3418ms], from last[200ms]
18-->Delta time from Start[3618ms], from last[200ms]
19-->Delta time from Start[3818ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
4.077: EnableBiasedLocking              [      11          2              2    ]      [     0     0     0     0     0    ]  2  
Total time for which application threads were stopped: 0.0000824 seconds
20-->Delta time from Start[4018ms], from last[200ms]
21-->Delta time from Start[4218ms], from last[200ms]
22-->Delta time from Start[4418ms], from last[200ms]
23-->Delta time from Start[4618ms], from last[200ms]
24-->Delta time from Start[4818ms], from last[200ms]
25-->Delta time from Start[5018ms], from last[200ms]
26-->Delta time from Start[5218ms], from last[200ms]
27-->Delta time from Start[5418ms], from last[200ms]
28-->Delta time from Start[5618ms], from last[200ms]
29-->Delta time from Start[5818ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
6.077: no vm operation                  [      11          2              2    ]      [     0     0     0     0     0    ]  2  
Total time for which application threads were stopped: 0.0000664 seconds
30-->Delta time from Start[6018ms], from last[200ms]
31-->Delta time from Start[6218ms], from last[200ms]
32-->Delta time from Start[6418ms], from last[200ms]
33-->Delta time from Start[6618ms], from last[200ms]
34-->Delta time from Start[6818ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
7.078: no vm operation                  [      11          2              2    ]      [     0     0     0     0     0    ]  2  
Total time for which application threads were stopped: 0.0000624 seconds
35-->Delta time from Start[7019ms], from last[201ms]
36-->Delta time from Start[7219ms], from last[200ms]
37-->Delta time from Start[7419ms], from last[200ms]
38-->Delta time from Start[7619ms], from last[200ms]
39-->Delta time from Start[7819ms], from last[200ms]
40-->Delta time from Start[8019ms], from last[200ms]
41-->Delta time from Start[8219ms], from last[200ms]
42-->Delta time from Start[8419ms], from last[200ms]
43-->Delta time from Start[8619ms], from last[200ms]
44-->Delta time from Start[8819ms], from last[200ms]
45-->Delta time from Start[9019ms], from last[200ms]
46-->Delta time from Start[9219ms], from last[200ms]
47-->Delta time from Start[9419ms], from last[200ms]
48-->Delta time from Start[9619ms], from last[200ms]
49-->Delta time from Start[9819ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
10.080: no vm operation                  [      11          2              2    ]      [  3206     0  3206     0     0    ]  2  
Total time for which application threads were stopped: 3.2066346 seconds
50-->Delta time from Start[13191ms], from last[3372ms]
51-->Delta time from Start[13391ms], from last[200ms]
52-->Delta time from Start[13591ms], from last[200ms]
53-->Delta time from Start[13791ms], from last[200ms]
54-->Delta time from Start[13991ms], from last[200ms]
55-->Delta time from Start[14191ms], from last[200ms]
56-->Delta time from Start[14391ms], from last[200ms]
57-->Delta time from Start[14591ms], from last[200ms]
58-->Delta time from Start[14791ms], from last[200ms]
59-->Delta time from Start[14991ms], from last[200ms]
60-->Delta time from Start[15191ms], from last[200ms]
61-->Delta time from Start[15391ms], from last[200ms]
62-->Delta time from Start[15591ms], from last[200ms]
63-->Delta time from Start[15791ms], from last[200ms]
64-->Delta time from Start[15991ms], from last[200ms]
65-->Delta time from Start[16191ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
16.288: no vm operation                  [      11          2              2    ]      [  1227     0  1227     0     0    ]  2  
Total time for which application threads were stopped: 1.2273317 seconds
66-->Delta time from Start[17420ms], from last[1229ms]
67-->Delta time from Start[17620ms], from last[200ms]
68-->Delta time from Start[17820ms], from last[200ms]
69-->Delta time from Start[18020ms], from last[200ms]
70-->Delta time from Start[18221ms], from last[201ms]
71-->Delta time from Start[18421ms], from last[200ms]
72-->Delta time from Start[18621ms], from last[200ms]
73-->Delta time from Start[18821ms], from last[200ms]
74-->Delta time from Start[19021ms], from last[200ms]
75-->Delta time from Start[19221ms], from last[200ms]
76-->Delta time from Start[19421ms], from last[200ms]
77-->Delta time from Start[19621ms], from last[200ms]
78-->Delta time from Start[19821ms], from last[200ms]
79-->Delta time from Start[20021ms], from last[200ms]
80-->Delta time from Start[20221ms], from last[200ms]
81-->Delta time from Start[20421ms], from last[200ms]
82-->Delta time from Start[20621ms], from last[200ms]
83-->Delta time from Start[20821ms], from last[200ms]
84-->Delta time from Start[21021ms], from last[200ms]
85-->Delta time from Start[21221ms], from last[200ms]
86-->Delta time from Start[21421ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
21.517: no vm operation                  [      11          2              2    ]      [   229     0   229     0     0    ]  2  
Total time for which application threads were stopped: 0.2291550 seconds
87-->Delta time from Start[21651ms], from last[230ms]
88-->Delta time from Start[21851ms], from last[200ms]
89-->Delta time from Start[22051ms], from last[200ms]
90-->Delta time from Start[22251ms], from last[200ms]
91-->Delta time from Start[22451ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
22.747: no vm operation                  [      11          1              2    ]      [  3324     0  3324     0     0    ]  1  
Total time for which application threads were stopped: 3.3249626 seconds
92-->Delta time from Start[22651ms], from last[200ms]
93-->Delta time from Start[26176ms], from last[3525ms]
94-->Delta time from Start[26376ms], from last[200ms]
95-->Delta time from Start[26576ms], from last[200ms]
96-->Delta time from Start[26776ms], from last[200ms]
97-->Delta time from Start[26976ms], from last[200ms]
98-->Delta time from Start[27176ms], from last[200ms]
99-->Delta time from Start[27376ms], from last[200ms]
100-->Delta time from Start[27576ms], from last[200ms]
101-->Delta time from Start[27776ms], from last[200ms]
102-->Delta time from Start[27976ms], from last[200ms]
103-->Delta time from Start[28176ms], from last[200ms]
104-->Delta time from Start[28376ms], from last[200ms]
105-->Delta time from Start[28576ms], from last[200ms]
106-->Delta time from Start[28776ms], from last[200ms]
107-->Delta time from Start[28976ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
29.073: no vm operation                  [      11          2              2    ]      [  1268     0  1268     0     0    ]  2  
Total time for which application threads were stopped: 1.2689592 seconds
108-->Delta time from Start[30247ms], from last[1271ms]
109-->Delta time from Start[30447ms], from last[200ms]
110-->Delta time from Start[30647ms], from last[200ms]
111-->Delta time from Start[30847ms], from last[200ms]
112-->Delta time from Start[31047ms], from last[200ms]
113-->Delta time from Start[31247ms], from last[200ms]
114-->Delta time from Start[31447ms], from last[200ms]
115-->Delta time from Start[31647ms], from last[200ms]
116-->Delta time from Start[31847ms], from last[200ms]
117-->Delta time from Start[32047ms], from last[200ms]
118-->Delta time from Start[32247ms], from last[200ms]
119-->Delta time from Start[32447ms], from last[200ms]
120-->Delta time from Start[32647ms], from last[200ms]
121-->Delta time from Start[32847ms], from last[200ms]
122-->Delta time from Start[33047ms], from last[200ms]
123-->Delta time from Start[33247ms], from last[200ms]
124-->Delta time from Start[33447ms], from last[200ms]
125-->Delta time from Start[33647ms], from last[200ms]
126-->Delta time from Start[33847ms], from last[200ms]
127-->Delta time from Start[34047ms], from last[200ms]
128-->Delta time from Start[34247ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
34.345: no vm operation                  [      11          2              2    ]      [   243     0   243     0     0    ]  2  
Total time for which application threads were stopped: 0.2436965 seconds
129-->Delta time from Start[34493ms], from last[246ms]
130-->Delta time from Start[34693ms], from last[200ms]
131-->Delta time from Start[34893ms], from last[200ms]
132-->Delta time from Start[35093ms], from last[200ms]
133-->Delta time from Start[35293ms], from last[200ms]
134-->Delta time from Start[35493ms], from last[200ms]
135-->Delta time from Start[35693ms], from last[200ms]
136-->Delta time from Start[35893ms], from last[200ms]
137-->Delta time from Start[36093ms], from last[200ms]
138-->Delta time from Start[36293ms], from last[200ms]
139-->Delta time from Start[36493ms], from last[200ms]

Process finished with exit code 1

RUNTIME RESULTS WITHOUT PAUSES
When MAKE_THE_JVM_PAUSE_UNEXPECTEDLY is false, no such pauses happen (actually, they are just exceedingly brief as they should be):


[GC (Allocation Failure) [PSYoungGen: 512K->384K(1024K)] 512K->384K(523776K), 0.0003767 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.044: ParallelGCFailedAllocation       [       5          0              0    ]      [     0     0     0     0     0    ]  0  
Total time for which application threads were stopped: 0.0004737 seconds
[GC (Allocation Failure) [PSYoungGen: 896K->496K(1024K)] 896K->504K(523776K), 0.0004580 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.055: ParallelGCFailedAllocation       [       5          0              0    ]      [     0     0     0     0     0    ]  0  
Total time for which application threads were stopped: 0.0005382 seconds
[GC (Allocation Failure) [PSYoungGen: 1005K->496K(1024K)] 1013K->592K(523776K), 0.0005466 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.066: ParallelGCFailedAllocation       [      10          0              1    ]      [     0     0     0     0     0    ]  0  
Total time for which application threads were stopped: 0.0006365 seconds
[GC (Allocation Failure) [PSYoungGen: 1008K->480K(1536K)] 1104K->656K(524288K), 0.0006778 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.074: ParallelGCFailedAllocation       [      10          0              0    ]      [     0     0     0     0     0    ]  0  
Total time for which application threads were stopped: 0.0007683 seconds
[GC (Allocation Failure) [PSYoungGen: 1502K->512K(1536K)] 1678K->998K(524288K), 0.0005509 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.092: ParallelGCFailedAllocation       [      11          1              0    ]      [     0     0     0     0     0    ]  0  
Total time for which application threads were stopped: 0.0007504 seconds
[GC (Allocation Failure) [PSYoungGen: 1534K->995K(2560K)] 2021K->2045K(525312K), 0.0005857 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.093: ParallelGCFailedAllocation       [      11          0              0    ]      [     0     0     0     0     0    ]  0  
Total time for which application threads were stopped: 0.0006562 seconds
[GC (Allocation Failure) [PSYoungGen: 2528K->1523K(3072K)] 3578K->3620K(525824K), 0.0006678 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.094: ParallelGCFailedAllocation       [      11          0              0    ]      [     0     0     0     0     0    ]  0  
Total time for which application threads were stopped: 0.0007407 seconds
[GC (Allocation Failure) [PSYoungGen: 3055K->2560K(5120K)] 5152K->5225K(527872K), 0.0007075 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.095: ParallelGCFailedAllocation       [      11          0              1    ]      [     0     0     0     0     0    ]  0  
Total time for which application threads were stopped: 0.0007883 seconds
[GC (Allocation Failure) [PSYoungGen: 5116K->3072K(5632K)] 7782K->7781K(528384K), 0.0008909 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.096: ParallelGCFailedAllocation       [      11          0              1    ]      [     0     0     0     0     0    ]  0  
Total time for which application threads were stopped: 0.0011088 seconds
[GC (Allocation Failure) [PSYoungGen: 5630K->4608K(7680K)] 10340K->10450K(530432K), 0.0010750 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.097: ParallelGCFailedAllocation       [      11          0              1    ]      [     0     0     0     0     1    ]  0  
Total time for which application threads were stopped: 0.0011544 seconds
[GC (Allocation Failure) [PSYoungGen: 7675K->3392K(8704K)] 13518K->13473K(531456K), 0.0013864 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.098: ParallelGCFailedAllocation       [      11          0              1    ]      [     0     0     0     0     1    ]  0  
Total time for which application threads were stopped: 0.0014720 seconds
[GC (Allocation Failure) [PSYoungGen: 6459K->3360K(11264K)] 16540K->16492K(534016K), 0.0011277 secs] [Times: user=0.05 sys=0.02, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.100: ParallelGCFailedAllocation       [      11          0              1    ]      [     0     0     0     0     1    ]  0  
Total time for which application threads were stopped: 0.0012160 seconds
[GC (Allocation Failure) [PSYoungGen: 8479K->5600K(11264K)] 21611K->21775K(534016K), 0.0010645 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.102: ParallelGCFailedAllocation       [      11          0              1    ]      [     0     0     0     0     1    ]  0  
Total time for which application threads were stopped: 0.0011504 seconds
0-->Delta time from Start[0ms], from last[0ms]
1-->Delta time from Start[212ms], from last[212ms]
2-->Delta time from Start[414ms], from last[202ms]
3-->Delta time from Start[615ms], from last[201ms]
4-->Delta time from Start[815ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
1.102: no vm operation                  [      11          2              2    ]      [     0     0     0     0     0    ]  2  
Total time for which application threads were stopped: 0.0000689 seconds
5-->Delta time from Start[1015ms], from last[200ms]
6-->Delta time from Start[1215ms], from last[200ms]
7-->Delta time from Start[1415ms], from last[200ms]
8-->Delta time from Start[1615ms], from last[200ms]
9-->Delta time from Start[1815ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
2.102: no vm operation                  [      11          2              2    ]      [     0     0     0     0     0    ]  2  
Total time for which application threads were stopped: 0.0000589 seconds
10-->Delta time from Start[2015ms], from last[200ms]
11-->Delta time from Start[2215ms], from last[200ms]
12-->Delta time from Start[2415ms], from last[200ms]
13-->Delta time from Start[2615ms], from last[200ms]
14-->Delta time from Start[2815ms], from last[200ms]
15-->Delta time from Start[3015ms], from last[200ms]
16-->Delta time from Start[3215ms], from last[200ms]
17-->Delta time from Start[3415ms], from last[200ms]
18-->Delta time from Start[3615ms], from last[200ms]
19-->Delta time from Start[3815ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
4.075: EnableBiasedLocking              [      11          2              2    ]      [     0     0     0     0     0    ]  2  
Total time for which application threads were stopped: 0.0000764 seconds
20-->Delta time from Start[4015ms], from last[200ms]
21-->Delta time from Start[4215ms], from last[200ms]
22-->Delta time from Start[4415ms], from last[200ms]
23-->Delta time from Start[4615ms], from last[200ms]
24-->Delta time from Start[4815ms], from last[200ms]
25-->Delta time from Start[5015ms], from last[200ms]
26-->Delta time from Start[5215ms], from last[200ms]
27-->Delta time from Start[5415ms], from last[200ms]
28-->Delta time from Start[5615ms], from last[200ms]
29-->Delta time from Start[5815ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
6.076: no vm operation                  [      11          2              2    ]      [     0     0     0     0     0    ]  2  
Total time for which application threads were stopped: 0.0000762 seconds
30-->Delta time from Start[6015ms], from last[200ms]
31-->Delta time from Start[6215ms], from last[200ms]
32-->Delta time from Start[6415ms], from last[200ms]
33-->Delta time from Start[6615ms], from last[200ms]
34-->Delta time from Start[6815ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
7.077: no vm operation                  [      11          2              2    ]      [     0     0     0     0     0    ]  2  
Total time for which application threads were stopped: 0.0000616 seconds
35-->Delta time from Start[7015ms], from last[200ms]
36-->Delta time from Start[7215ms], from last[200ms]
37-->Delta time from Start[7415ms], from last[200ms]
38-->Delta time from Start[7615ms], from last[200ms]
39-->Delta time from Start[7815ms], from last[200ms]
40-->Delta time from Start[8015ms], from last[200ms]
41-->Delta time from Start[8215ms], from last[200ms]
42-->Delta time from Start[8415ms], from last[200ms]
43-->Delta time from Start[8615ms], from last[200ms]
44-->Delta time from Start[8815ms], from last[200ms]
45-->Delta time from Start[9015ms], from last[200ms]
46-->Delta time from Start[9215ms], from last[200ms]
47-->Delta time from Start[9415ms], from last[200ms]
48-->Delta time from Start[9615ms], from last[200ms]
49-->Delta time from Start[9815ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
10.078: no vm operation                  [      11          2              2    ]      [     0     0     0     0     0    ]  2  
Total time for which application threads were stopped: 0.0000689 seconds
50-->Delta time from Start[10015ms], from last[200ms]
51-->Delta time from Start[10215ms], from last[200ms]
52-->Delta time from Start[10415ms], from last[200ms]
53-->Delta time from Start[10615ms], from last[200ms]
54-->Delta time from Start[10815ms], from last[200ms]
55-->Delta time from Start[11015ms], from last[200ms]
56-->Delta time from Start[11215ms], from last[200ms]
57-->Delta time from Start[11415ms], from last[200ms]
58-->Delta time from Start[11615ms], from last[200ms]
59-->Delta time from Start[11815ms], from last[200ms]
60-->Delta time from Start[12015ms], from last[200ms]
61-->Delta time from Start[12215ms], from last[200ms]
62-->Delta time from Start[12415ms], from last[200ms]
63-->Delta time from Start[12615ms], from last[200ms]
64-->Delta time from Start[12815ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
13.078: no vm operation                  [      11          2              2    ]      [     0     0     0     0     0    ]  2  
Total time for which application threads were stopped: 0.0000613 seconds
65-->Delta time from Start[13015ms], from last[200ms]
66-->Delta time from Start[13215ms], from last[200ms]
67-->Delta time from Start[13415ms], from last[200ms]
68-->Delta time from Start[13615ms], from last[200ms]
69-->Delta time from Start[13815ms], from last[200ms]
70-->Delta time from Start[14015ms], from last[200ms]
71-->Delta time from Start[14215ms], from last[200ms]
72-->Delta time from Start[14415ms], from last[200ms]
73-->Delta time from Start[14615ms], from last[200ms]
74-->Delta time from Start[14815ms], from last[200ms]
75-->Delta time from Start[15015ms], from last[200ms]
76-->Delta time from Start[15215ms], from last[200ms]
77-->Delta time from Start[15415ms], from last[200ms]
78-->Delta time from Start[15615ms], from last[200ms]
79-->Delta time from Start[15815ms], from last[200ms]
80-->Delta time from Start[16015ms], from last[200ms]
81-->Delta time from Start[16215ms], from last[200ms]
82-->Delta time from Start[16415ms], from last[200ms]
83-->Delta time from Start[16615ms], from last[200ms]
84-->Delta time from Start[16815ms], from last[200ms]
85-->Delta time from Start[17015ms], from last[200ms]
86-->Delta time from Start[17215ms], from last[200ms]
87-->Delta time from Start[17415ms], from last[200ms]
88-->Delta time from Start[17615ms], from last[200ms]
89-->Delta time from Start[17815ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
18.079: no vm operation                  [      11          2              2    ]      [     0     0     0     0     0    ]  2  
Total time for which application threads were stopped: 0.0000654 seconds
90-->Delta time from Start[18015ms], from last[200ms]
91-->Delta time from Start[18215ms], from last[200ms]
92-->Delta time from Start[18415ms], from last[200ms]
93-->Delta time from Start[18615ms], from last[200ms]
94-->Delta time from Start[18815ms], from last[200ms]
95-->Delta time from Start[19015ms], from last[200ms]
96-->Delta time from Start[19215ms], from last[200ms]
97-->Delta time from Start[19415ms], from last[200ms]
98-->Delta time from Start[19615ms], from last[200ms]
99-->Delta time from Start[19815ms], from last[200ms]
100-->Delta time from Start[20015ms], from last[200ms]
101-->Delta time from Start[20215ms], from last[200ms]
102-->Delta time from Start[20415ms], from last[200ms]
103-->Delta time from Start[20615ms], from last[200ms]
104-->Delta time from Start[20815ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
21.081: no vm operation                  [      11          2              2    ]      [     0     0     0     0     0    ]  2  
Total time for which application threads were stopped: 0.0000599 seconds
105-->Delta time from Start[21015ms], from last[200ms]
106-->Delta time from Start[21215ms], from last[200ms]
107-->Delta time from Start[21415ms], from last[200ms]
108-->Delta time from Start[21615ms], from last[200ms]
109-->Delta time from Start[21815ms], from last[200ms]
110-->Delta time from Start[22015ms], from last[200ms]
111-->Delta time from Start[22215ms], from last[200ms]
112-->Delta time from Start[22415ms], from last[200ms]
113-->Delta time from Start[22615ms], from last[200ms]
114-->Delta time from Start[22815ms], from last[200ms]
115-->Delta time from Start[23015ms], from last[200ms]
116-->Delta time from Start[23215ms], from last[200ms]
117-->Delta time from Start[23415ms], from last[200ms]
118-->Delta time from Start[23615ms], from last[200ms]
119-->Delta time from Start[23815ms], from last[200ms]
120-->Delta time from Start[24015ms], from last[200ms]
121-->Delta time from Start[24215ms], from last[200ms]
122-->Delta time from Start[24415ms], from last[200ms]
123-->Delta time from Start[24615ms], from last[200ms]
124-->Delta time from Start[24815ms], from last[200ms]
125-->Delta time from Start[25015ms], from last[200ms]
126-->Delta time from Start[25215ms], from last[200ms]
127-->Delta time from Start[25415ms], from last[200ms]
128-->Delta time from Start[25615ms], from last[200ms]
129-->Delta time from Start[25815ms], from last[200ms]
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
26.085: no vm operation                  [      11          2              2    ]      [     0     0     0     0     0    ]  2  
Total time for which application threads were stopped: 0.0000626 seconds
130-->Delta time from Start[26015ms], from last[200ms]
131-->Delta time from Start[26215ms], from last[200ms]
132-->Delta time from Start[26415ms], from last[200ms]
133-->Delta time from Start[26615ms], from last[200ms]
134-->Delta time from Start[26815ms], from last[200ms]
135-->Delta time from Start[27015ms], from last[200ms]
136-->Delta time from Start[27215ms], from last[200ms]
137-->Delta time from Start[27415ms], from last[200ms]
138-->Delta time from Start[27615ms], from last[200ms]
139-->Delta time from Start[27815ms], from last[200ms]
140-->Delta time from Start[28015ms], from last[200ms]
141-->Delta time from Start[28215ms], from last[200ms]
142-->Delta time from Start[28415ms], from last[200ms]
143-->Delta time from Start[28615ms], from last[200ms]
144-->Delta time from Start[28815ms], from last[200ms]
145-->Delta time from Start[29015ms], from last[200ms]
146-->Delta time from Start[29215ms], from last[200ms]
147-->Delta time from Start[29415ms], from last[200ms]
148-->Delta time from Start[29615ms], from last[200ms]
149-->Delta time from Start[29815ms], from last[200ms]
150-->Delta time from Start[30015ms], from last[200ms]
151-->Delta time from Start[30215ms], from last[200ms]
152-->Delta time from Start[30415ms], from last[200ms]
153-->Delta time from Start[30615ms], from last[200ms]
154-->Delta time from Start[30815ms], from last[200ms]
155-->Delta time from Start[31015ms], from last[200ms]
156-->Delta time from Start[31215ms], from last[200ms]
157-->Delta time from Start[31415ms], from last[200ms]
158-->Delta time from Start[31615ms], from last[200ms]
159-->Delta time from Start[31815ms], from last[200ms]
160-->Delta time from Start[32015ms], from last[200ms]
161-->Delta time from Start[32215ms], from last[200ms]

Process finished with exit code 1
2 weeks ago
This happens on both JDK 1.8.0 (Java 8) and JDK 9.0.4 (Note the new version format for Java 9)

I've looked extensively into the various JVM memory management complaints out there and this seems to be a safepoint oddity.  Man do I ever hope this is because I've overlooked something obvious or silly or have otherwise forgotten something over the years.

Here are the issues simply listed out.

1. The example code below has been paired down tremendously from a much larger project, so don't expect it to make algorithmic sense.
2. I'm looping through a large (5000x5000 element) boolean array.
3. When that loop is *within a method* (called "sweep()"), it periodically causes phantom pauses across all threads, however no garbage collection is being run (as verified by JvisualVM and runtime options).
4. Inside the code at line 42 you'll see a "MAKE_THE_JVM_PAUSE_UNEXPECTEDLY" boolean.  Setting that to true will cause a call to sweep() and show the pauses.  Setting that false will cause the exact same code to be run without the method call.
5. I've tried that method call with and without the boolean allocation internally, so the fact that the reference to the boolean[][] is passed in doesn't matter.  The pause happens anyway.
6. IMPORTANT: There are two primary threads here.  The first one fired off is a simple heartbeat thread that just loops and prints the current elapsed time.  This allows us to see the JVM pause.  The 2nd thread is actually the "main" thread where the computation happens (the thread of public static void main()).
7. In the runtime examples below, the pauses start happening right at heartbeat #49.

2 weeks ago

This was careless naming IMO.  The Java Collections should never have sanctioned a (List).remove(int) to remove at a specific slot within the List.

It should have been named "removeAt(int)" or similar.

This probably happened because Java Collections far predated any consideration of Auto Boxing/Unboxing (Java 5 I believe), so it never occurred to anyone that an "intention" conflict might happen.

3 weeks ago

Stephan van Hulst wrote:I think you'll have to write an example we can run for us to help you with this.



Yes: Planning on it.  Have to get all my ducks in a row first.

The changes in jdk9 and 10 regarding how the safepoints work will be part of what I need to fault-isolate this thing, and that takes some time.

I'm really not alone in this either.  There are a lot of folks wandering directly into a crazy non-GC safepoint pause.  Looking to the Java bug database, I can see a few related and hard to trace down bug entries.

But I need to know if the issue is mine or not before further questioning the JVM.
3 weeks ago
Ok, it's almost a safepoint problem: The JVM is reporting a massive pause (4+ seconds), but with a blank vmop.  Huh?  Still chasing this down.

On 1.8.0.  Going to try 9, etc.
3 weeks ago

Not just Netbeans.

When I started in java (eons ago), I was part of a consultant house that was called in to solve various problems with customer code (or cause some of our own ).  I have to say that every piece of actual development code I've ever come across either in house or done by the customer has been with the member variables (etc.) at the end of the class.

Further, the psv main() method is also at the end, if it's used.

I've been "out of the loop" for some time and somehow it seems that the trend reversed itself somewhere along the line.  Beats me why.

The OP is 100% correct.  Get the data out of the way.

3 weeks ago

I'm chasing a weird JVM pause regarding the access of a fairly large (5000x5000) array.  It certainly is not big in the scheme of things these days however.  The contents are primitives (booleans), so it should be ~25MB or so.

It's not a thread lockout either, because if I remove any and all synchronization from the code, it still happens the same as before.  All threads, stopped.

1. If I replace the array reads/writes with a burner loop (not a sleep (on purpose), but a simple loop + check for current time) for 5 seconds, the problem never occurs.
2. ^^^^So I'm assuming it's either a GC or a heap shuffling thing.

But before I go and torment anyone with a scaled down version of the offending code, I could use an answer first:

Do I have to run the JVM with the -verbosegc (or similar) argument in order for VisualVM to get GC and/or allocation events?

3 weeks ago

David Simkulette wrote:That's the gerat thing about friendly forums like this one for me; I learn about things I had zero idea even existed. in this case "Unsafe class. "

Can't know about everything in all subjects !!

Thanks Thomas!



Well maybe don't spend too much time on it: Solaris is desperately trying to kill it outright, and sort of for Java 9, but wow are they experiencing significant pushback.  Their current plans are a little weird.

Watch this if you care to know the back story. Note: This video was made before they made up their minds about their precise course of action, but is some of what Solaris refers to as the "tragic" history of sun.misc.Unsafe:
I think it is fairly worthwhile to get a sense as to how this thing has been used (much to Solaris's chagrin).  Pretty interesting.

But again, understand two things:

1. sun.{mumble} is really not part of the standard language definition.  They really don't want you in there.
2. It's going away.

But a lot of facilities currently depend upon it, so I suppose we'll see if disaster strikes.

David Simkulette wrote:

I have to imagine the lock-freeness of the AtomicXXX classes, in this case AtomicBoolean, is a syntatic thing and under the surfaces, locks are involved. I may well be wrong but I am thinking if this weren't the case then there's be another method other than locks through which atomic transactions could be achieved.

I can't see how to do it outside of involving synchronization.



Well as I pointed out upthread, the source indicates that they're divining into the Unsafe class, which ultimately results in native calls.  I believe that the atomic nature of the objects is achieved that way.

David Simkulette wrote:

Jesper de Jong wrote:You can do this by writing your own ThreadSafeBoolean class with synchronized methods and it works, but the point of AtomicBoolean and the other classes in the package java.util.concurrent.atomic is that they are lock-free, which means that none of their methods ever blocks a thread. Your implementation with synchronized does block threads, if one thread is executing the methods on an instance of ThreadSafeBoolean than other threads who would try to execute the same method on the same instance are forced to wait.

The compareAndSwap() method actually corresponds to a machine instruction on your CPU: Compare and swap (Wikipedia).

For some reason there is no hardware atomic flip operation.



I have to imagine the lock-freeness of the AtomicXXX classes, in this case AtomicBoolean, is a syntatic thing and under the surfaces, locks are involved. I may well be wrong but I am thinking if this weren't the case then there's be another method other than locks through which atomic transactions could be achieved.

I can't see how to do it outside of involving synchronization.



Yes, I know of course that the locks will block all threads, but they are for exceedingly short periods of time (get/set/even swap).  The run()/call() facilities are just for "in-case" unforeseen scenarios.

In fact, I toyed with using ReentrantReadWriteLock, which I've used extensively in the past for an Alife app, for the get() cases in case there are a myriad of threads all reading at the same time.  But the overhead of the ReentrantLock code (look at the doc) specifically mentions the overhead involved, and in this case the get/set/negates are a far lighter execution footprint.

And because I'm so friggen tired, I botched the test harness.  Fixed:  Here's 3 threads pounding on the negate() of the same ThreadSafeBoolean:

Resulting in