Migrating from H2 to MS-SQL causes immediate GC errors. JIRA fails to start

[Joe Bloggs]

Version 8.0.0 of JIRA. Just moved it from H2 to MS-SQL. All DB configuration verified via config tool and by loggin into SQL server with the credentials. Immediately after startup:

Java HotSpot(TM) 64-Bit Server VM (25.181-b13) for windows-amd64 JRE (1.8.0_181-b13), built on Jul 7 2018 04:01:33 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 12581868k(9296252k free), swap 16120812k(12825160k free)
CommandLine flags: -XX:GCLogFileSize=20971520 -XX:InitialCodeCacheSize=33554432 -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=2147483648 -XX:NumberOfGCLogFiles=5 -XX:-OmitStackTraceInFastThrow -XX:+PrintGC -XX:+PrintGCCause -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:ReservedCodeCacheSize=536870912 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseGCLogFileRotation -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
2019-03-02T19:44:44.009+0000: 1.271: [GC (Allocation Failure) [PSYoungGen: 65536K->10724K(76288K)] 65536K->11478K(251392K), 0.0139732 secs] [Times: user=0.02 sys=0.05, real=0.02 secs] 
2019-03-02T19:44:44.243+0000: 1.506: [GC (Allocation Failure) [PSYoungGen: 76260K->7639K(141824K)] 77014K->8400K(316928K), 0.0088797 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
2019-03-02T19:44:45.228+0000: 2.493: [GC (Allocation Failure) [PSYoungGen: 138711K->10728K(141824K)] 139472K->16292K(316928K), 0.0129431 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
2019-03-02T19:44:45.868+0000: 3.120: [GC (Allocation Failure) [PSYoungGen: 141800K->10728K(272896K)] 147364K->18576K(448000K), 0.0122744 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-03-02T19:44:47.259+0000: 4.520: [GC (Allocation Failure) [PSYoungGen: 272872K->10728K(272896K)] 280720K->23223K(448000K), 0.0276264 secs] [Times: user=0.11 sys=0.00, real=0.03 secs] 
2019-03-02T19:44:48.978+0000: 6.229: [GC (Allocation Failure) [PSYoungGen: 272872K->17264K(541696K)] 285367K->29767K(716800K), 0.0206512 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
2019-03-02T19:44:50.462+0000: 7.728: [GC (Metadata GC Threshold) [PSYoungGen: 349648K->16807K(543232K)] 362151K->34538K(718336K), 0.0227124 secs] [Times: user=0.00 sys=0.03, real=0.03 secs] 
2019-03-02T19:44:50.493+0000: 7.751: [Full GC (Metadata GC Threshold) [PSYoungGen: 16807K->0K(543232K)] [ParOldGen: 17730K->26520K(175104K)] 34538K->26520K(718336K), [Metaspace: 20748K->20748K(1069056K)], 0.0676230 secs] [Times: user=0.20 sys=0.00, real=0.06 secs] 
2019-03-02T19:44:52.696+0000: 9.951: [GC (System.gc()) [PSYoungGen: 336434K->15919K(676864K)] 362955K->42448K(851968K), 0.0168736 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
2019-03-02T19:44:52.712+0000: 9.968: [Full GC (System.gc()) [PSYoungGen: 15919K->0K(676864K)] [ParOldGen: 26528K->33412K(175104K)] 42448K->33412K(851968K), [Metaspace: 32695K->32695K(1079296K)], 0.1358214 secs] [Times: user=0.33 sys=0.00, real=0.14 secs] 

 Plenty of memory free. Message in browser:

http://xxx.xxx.xxx.xxx:8080/secure/errors.jsp

Been searching, but haven't found similar thread - any ideas?

[Gonchik Tsymzhitov]

Hi! 

Could you set 4GB as Heap and G1GC , as gc collector algorithm ?

Cheers,

Gonchik Tsymzhitov

[Joe Bloggs]

Hi Gonchik, thank you for the prompt reply.

You got me back to the problem tonight and in the end it was beginner's error in not granting DBO to the jira user.

Below what else was being observed with the unsuccessful starts after GC changes, just in case it helps anyone. (as the test-connection worked and user had access to the DB so that it wasn't immediately obvious that they weren't able to create objects).

Have done both, alas it still goes bad quickly - in about 7 seconds the GC is full. Starting fine with H2 with otherwise exactly the same configuraiton. 

Java HotSpot(TM) 64-Bit Server VM (25.181-b13) for windows-amd64 JRE (1.8.0_181-b13), built on Jul 7 2018 04:01:33 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 12581868k(4449900k free), swap 16120812k(7951276k free)
CommandLine flags: -XX:GCLogFileSize=20971520 -XX:InitialCodeCacheSize=33554432 -XX:InitialHeapSize=2147483648 -XX:MaxHeapSize=4294967296 -XX:NumberOfGCLogFiles=5 -XX:-OmitStackTraceInFastThrow -XX:+PrintGC -XX:+PrintGCCause -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:ReservedCodeCacheSize=536870912 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:+UseGCLogFileRotation -XX:-UseLargePagesIndividualAllocation 
2019-03-03T00:18:45.013+0000: 1.429: [GC pause (G1 Evacuation Pause) (young), 0.0133356 secs]
[Parallel Time: 8.5 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 1429.0, Avg: 1429.1, Max: 1429.5, Diff: 0.6]
[Ext Root Scanning (ms): Min: 0.3, Avg: 0.9, Max: 1.3, Diff: 1.1, Sum: 3.6]
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Code Root Scanning (ms): Min: 0.2, Avg: 0.4, Max: 0.9, Diff: 0.7, Sum: 1.6]
[Object Copy (ms): Min: 6.7, Avg: 6.9, Max: 7.3, Diff: 0.6, Sum: 27.8]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 7.9, Avg: 8.3, Max: 8.4, Diff: 0.6, Sum: 33.1]
[GC Worker End (ms): Min: 1437.4, Avg: 1437.4, Max: 1437.4, Diff: 0.0]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 4.6 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 4.1 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.1 ms]
[Eden: 102.0M(102.0M)->0.0B(90.0M) Survivors: 0.0B->12.0M Heap: 102.0M(2048.0M)->11.6M(2048.0M)]
[Times: user=0.06 sys=0.00, real=0.02 secs] 
2019-03-03T00:18:45.857+0000: 2.266: [GC pause (G1 Evacuation Pause) (young), 0.0121669 secs]
[Parallel Time: 10.6 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 2266.5, Avg: 2266.5, Max: 2266.6, Diff: 0.0]
[Ext Root Scanning (ms): Min: 0.2, Avg: 0.5, Max: 1.2, Diff: 1.0, Sum: 2.1]
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.5, Max: 1.8, Diff: 1.8, Sum: 2.1]
[Object Copy (ms): Min: 8.4, Avg: 9.4, Max: 10.1, Diff: 1.7, Sum: 37.7]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.5, Max: 3, Diff: 2, Sum: 6]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 10.5, Avg: 10.5, Max: 10.5, Diff: 0.0, Sum: 42.0]
[GC Worker End (ms): Min: 2277.0, Avg: 2277.0, Max: 2277.1, Diff: 0.0]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 1.3 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.9 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.1 ms]
[Eden: 90.0M(90.0M)->0.0B(93.0M) Survivors: 12.0M->9216.0K Heap: 101.6M(2048.0M)->15.9M(2048.0M)]
[Times: user=0.06 sys=0.00, real=0.02 secs] 
2019-03-03T00:18:46.310+0000: 2.715: [GC pause (G1 Evacuation Pause) (young), 0.0056247 secs]
[Parallel Time: 4.0 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 2715.2, Avg: 2715.4, Max: 2716.0, Diff: 0.7]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.5, Diff: 0.5, Sum: 1.2]
[Update RS (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.7]
[Processed Buffers: Min: 0, Avg: 2.3, Max: 5, Diff: 5, Sum: 9]
[Scan RS (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.5]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 0.7]
[Object Copy (ms): Min: 2.6, Avg: 3.0, Max: 3.2, Diff: 0.6, Sum: 11.9]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 3.2, Avg: 3.7, Max: 3.9, Diff: 0.7, Sum: 15.0]
[GC Worker End (ms): Min: 2719.2, Avg: 2719.2, Max: 2719.2, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 1.5 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1.0 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.1 ms]
[Eden: 93.0M(93.0M)->0.0B(128.0M) Survivors: 9216.0K->10.0M Heap: 108.9M(2048.0M)->16.9M(2048.0M)]
[Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-03-03T00:18:46.904+0000: 3.321: [GC pause (G1 Evacuation Pause) (young), 0.0074668 secs]
[Parallel Time: 5.2 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 3320.9, Avg: 3320.9, Max: 3321.0, Diff: 0.0]
[Ext Root Scanning (ms): Min: 0.2, Avg: 0.3, Max: 0.4, Diff: 0.1, Sum: 1.2]
[Update RS (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.5]
[Processed Buffers: Min: 1, Avg: 2.3, Max: 5, Diff: 4, Sum: 9]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.3]
[Object Copy (ms): Min: 4.4, Avg: 4.5, Max: 4.6, Diff: 0.2, Sum: 18.0]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 5.0, Avg: 5.1, Max: 5.1, Diff: 0.0, Sum: 20.2]
[GC Worker End (ms): Min: 3326.0, Avg: 3326.0, Max: 3326.0, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 2.2 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1.7 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.1 ms]
[Eden: 128.0M(128.0M)->0.0B(731.0M) Survivors: 10.0M->12.0M Heap: 144.9M(2048.0M)->18.9M(2048.0M)]
[Times: user=0.06 sys=0.00, real=0.02 secs] 
2019-03-03T00:18:51.607+0000: 8.017: [GC pause (G1 Evacuation Pause) (young), 0.0268154 secs]
[Parallel Time: 11.6 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 8016.9, Avg: 8016.9, Max: 8017.0, Diff: 0.0]
[Ext Root Scanning (ms): Min: 0.3, Avg: 0.5, Max: 0.6, Diff: 0.4, Sum: 1.9]
[Update RS (ms): Min: 0.2, Avg: 0.3, Max: 0.5, Diff: 0.3, Sum: 1.2]
[Processed Buffers: Min: 1, Avg: 2.8, Max: 6, Diff: 5, Sum: 11]
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.4]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.7]
[Object Copy (ms): Min: 9.9, Avg: 10.1, Max: 10.3, Diff: 0.4, Sum: 40.5]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.5, Max: 3, Diff: 2, Sum: 6]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 11.2, Avg: 11.2, Max: 11.2, Diff: 0.0, Sum: 44.9]
[GC Worker End (ms): Min: 8028.2, Avg: 8028.2, Max: 8028.2, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.2 ms]
[Other: 15.0 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 14.1 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.3 ms]
[Eden: 731.0M(731.0M)->0.0B(1200.0M) Survivors: 12.0M->28.0M Heap: 749.9M(2048.0M)->34.4M(2048.0M)]
[Times: user=0.08 sys=0.00, real=0.03 secs] 
2019-03-03T00:18:52.029+0000: 8.440: [GC pause (Metadata GC Threshold) (young) (initial-mark), 0.0108086 secs]
[Parallel Time: 9.5 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 8440.1, Avg: 8440.4, Max: 8441.2, Diff: 1.1]
[Ext Root Scanning (ms): Min: 0.1, Avg: 1.3, Max: 3.5, Diff: 3.4, Sum: 5.4]
[Update RS (ms): Min: 0.0, Avg: 0.3, Max: 0.5, Diff: 0.5, Sum: 1.3]
[Processed Buffers: Min: 0, Avg: 2.5, Max: 5, Diff: 5, Sum: 10]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 0.8]
[Object Copy (ms): Min: 5.9, Avg: 7.2, Max: 7.8, Diff: 2.0, Sum: 28.8]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 8.3, Avg: 9.1, Max: 9.4, Diff: 1.1, Sum: 36.4]
[GC Worker End (ms): Min: 8449.5, Avg: 8449.5, Max: 8449.5, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 1.2 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.6 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.1 ms]
[Eden: 62.0M(1200.0M)->0.0B(1213.0M) Survivors: 28.0M->15.0M Heap: 96.4M(2048.0M)->21.9M(2048.0M)]
[Times: user=0.06 sys=0.00, real=0.02 secs] 
2019-03-03T00:18:52.045+0000: 8.451: [GC concurrent-root-region-scan-start]
2019-03-03T00:18:52.045+0000: 8.461: [GC concurrent-root-region-scan-end, 0.0105354 secs]
2019-03-03T00:18:52.045+0000: 8.461: [GC concurrent-mark-start]
2019-03-03T00:18:52.076+0000: 8.481: [GC concurrent-mark-end, 0.0196468 secs]
2019-03-03T00:18:52.076+0000: 8.481: [GC remark 2019-03-03T00:18:52.076+0000: 8.481: [Finalize Marking, 0.0001491 secs] 2019-03-03T00:18:52.076+0000: 8.481: [GC ref-proc, 0.0001213 secs] 2019-03-03T00:18:52.076+0000: 8.482: [Unloading, 0.0033068 secs], 0.0038557 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-03-03T00:18:52.076+0000: 8.485: [GC cleanup 24M->24M(2048M), 0.0010332 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-03-03T00:18:54.404+0000: 10.819: [Full GC (System.gc()) 320M->32M(2048M), 0.1342166 secs]
[Eden: 299.0M(1213.0M)->0.0B(1228.0M) Survivors: 15.0M->0.0B Heap: 320.9M(2048.0M)->32.4M(2048.0M)], [Metaspace: 32486K->32486K(1079296K)]
[Times: user=0.19 sys=0.00, real=0.14 secs]  

 Just to confirm I have followed

https://confluence.atlassian.com/adminjiraserver073/connecting-jira-applications-to-sql-server-2014-861253050.html

to setup the MS-SQL side .

No other log files are populated apart from commons-daemon, which looks ok.

[2019-03-03 00:18:43] [info] [ 3784] Commons Daemon procrun (1.1.0.0 64-bit) started
[2019-03-03 00:18:43] [info] [ 3784] Running 'JIRASoftware020319135737' Service...
[2019-03-03 00:18:43] [info] [ 4600] Starting service...
[2019-03-03 00:18:44] [info] [ 4600] Service started in 1170 ms.

I suspect something else is missin 

[Joe Bloggs]

Accepting answer as it indirectly helped with resolution. 

[Gonchik Tsymzhitov]

About connection that's good to check before :)

if you need to review in the future, you read that article 

https://community.atlassian.com/t5/Marketplace-Apps-articles/How-do-you-analyze-GC-logs-thread-dumps-and-head-dumps/ba-p/985787