1 2 Previous Next 17 Replies Latest reply on Sep 14, 2015 6:59 AM by jhberges

    How come this simplistic test generate OOM behavior?

    jhberges

      Hello all.

       

      We've been testing the Jena API in rdf_semantic_graph_support_for_apache_jena_2.11.1_with_12101_server_patch_build0529 and observer the following behavior, based on the attached test:

      oom.png

       

      The test is rather simplistic - any help is appreciated!

      Thanks, Jan-Helge.

       

      public class OracleSemTxIntegrationWithSpringITCase {

          private OracleDataSource oracleDataSource;

          private OraclePool oraclePool;


          @Before

          public void before() throws SQLException {

              java.util.Properties prop = new java.util.Properties();

              prop.setProperty("MinLimit", "2");     // the cache size is 2 at least

              prop.setProperty("MaxLimit", "10");

              prop.setProperty("InitialLimit", "2"); // create 2 connections at startup

              prop.setProperty("InactivityTimeout", "200");    //  seconds

              prop.setProperty("AbandonedConnectionTimeout", "100");  //  seconds

              prop.setProperty("MaxStatementsLimit", "10");

              prop.setProperty("PropertyCheckInterval", "60"); // seconds

       

       

              oracleDataSource = new OracleDataSource();

              oracleDataSource.setURL("jdbc:oracle:thin:@**********");

              oracleDataSource.setUser("rdfuser");

              oracleDataSource.setPassword("****");

              oracleDataSource.setConnectionProperties(prop);

       

       

              oraclePool = new OraclePool(oracleDataSource);

          }

       

       

          @Test

          public void testTransactionHandlingViaJdbcTransactions() throws Exception {

              final Oracle oracle1 = oraclePool.getOracle();

              final Oracle oracle2 = oraclePool.getOracle();

              final Oracle oracle3 = oraclePool.getOracle();

       

       

              final GraphOracleSem graph1 = new GraphOracleSem(oracle1, OracleMetadataDaoITCase.INTEGRATION_TEST_MODEL);

              final Model model1 = new ModelOracleSem(graph1);

              final GraphOracleSem graph2 = new GraphOracleSem(oracle2, OracleMetadataDaoITCase.INTEGRATION_TEST_MODEL);

              final Model model2 = new ModelOracleSem(graph2);

              GraphOracleSem graph3 = new GraphOracleSem(oracle3, OracleMetadataDaoITCase.INTEGRATION_TEST_MODEL);

              Model model3 = new ModelOracleSem(graph3);

       

       

              removePersons(model3);

              model3.commit();

              model3.close();

              graph3 = new GraphOracleSem(oracle3, OracleMetadataDaoITCase.INTEGRATION_TEST_MODEL);

              model3 = new ModelOracleSem(graph3);

       

       

              model1.add(model1.createResource("http://www.tv2.no/people/person-1"), DC.description, "A dude");

              model2.add(model1.createResource("http://www.tv2.no/people/person-2"), DC.description, "Another dude");

       

       

              int countPersons = countPersons(model3);

              assertEquals(0, countPersons);

       

       

              model1.commit();

              countPersons = countPersons(model3);

              assertEquals(1, countPersons);

       

       

              System.err.println("Committing connection #1\n");

              model2.commit();

              countPersons = countPersons(model3);

              assertEquals(2, countPersons);

       

       

              oracle1.commitTransaction();

              oracle2.commitTransaction();

              oracle3.commitTransaction();

       

       

              model1.close();

              model2.close();

              model3.close();

       

       

              oracle1.dispose();

              oracle2.dispose();

              oracle3.dispose();

              System.err.println("all disposed");

          }

       

       

          public static void main(String ...args) throws Exception {

              OracleSemTxIntegrationWithSpringITCase me = new OracleSemTxIntegrationWithSpringITCase();

              me.before();

              System.err.println("START");

              Stopwatch sw = Stopwatch.createStarted();

              for(int n = 0; n < 1000; n++) {

                  System.err.println(" --- " + n);

                  me.testTransactionHandlingViaJdbcTransactions();

              }

              System.err.println("DONE: " + sw.stop());

              me.after();

              System.err.println("DONE with all");

          }

          @After

          public void after() throws SQLException {

              oracleDataSource.close();

          }

       

       

          private int countPersons(final Model model) {

              return listPersons(model).size();

          }

       

       

          private void removePersons(final Model model) {

              System.err.println("Listing persons to remove...\n");

              final List<Resource> persons = listPersons(model);

              System.err.printf("Removing %d persons\n", persons.size());

              persons.stream().forEach(per -> model.removeAll(per, null, null));

          }

       

       

          private List<Resource> listPersons(final Model model) {

              final List<Resource> persons = Lists.newArrayList();

              ExtendedIterator<Resource> iter = model.listSubjects()

                  .filterKeep(new Filter<Resource>() {

                      @Override

                      public boolean accept(Resource o) {

                          return o.getURI().startsWith("http://www.tv2.no/people/person-");

                      }

                  })

                  ;

              iter.forEachRemaining(item -> persons.add(item));

              iter.close();

              return persons;

          }

      }

        • 1. Re: How come this simplistic test generate OOM behavior?
          jhberges

          I should note that it's the main() method that's causing the behavior - the test works flawlessly strictly functional.

          The server version is Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production (Spatial & Graph)

          • 2. Re: How come this simplistic test generate OOM behavior?
            alwu-Oracle

            Hi Jan-Helge,

             

            Thanks for uploading a nice chart    It is good to hear that all functions worked flawlessly.

             

            Now, it looks like that the memory consumption went up in a straight line. Can you please enable GC tracing?

            Also, what is heap size that you chose?

             

            Zhe Wu

            • 3. Re: How come this simplistic test generate OOM behavior?
              jhberges

              Hi!

               

              For this example the JVM was running with "default eclipse" heap size, which seems to be approx 3Gb.

              Setting a hard limit to the heap (say -Xmx50m) will cause an OutOfMemory.

               

              I'll do a run with GC tracing enabled (or, if it's helpful; I can create a Flight Recording)

               

              BR. Jan-Helge

              • 4. Re: Re: How come this simplistic test generate OOM behavior?
                jhberges

                The GC log below, after running with options -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -verbose:gc, yielding the following heap graph:

                mem.png

                 

                1.433: [GC (Allocation Failure) [PSYoungGen: 49152K->6291K(57344K)] 49152K->6307K(188416K), 0.0061355 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                2.420: [GC (Allocation Failure) [PSYoungGen: 55443K->7979K(57344K)] 55459K->8099K(188416K), 0.0073678 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

                13.815: [GC (Allocation Failure) [PSYoungGen: 57131K->8187K(57344K)] 57251K->12336K(188416K), 0.0127021 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                20.890: [GC (Allocation Failure) [PSYoungGen: 57339K->8161K(57344K)] 61488K->19493K(188416K), 0.0209730 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]

                25.194: [GC (Allocation Failure) [PSYoungGen: 57313K->8177K(56320K)] 68645K->26761K(187392K), 0.0093300 secs] [Times: user=0.01 sys=0.05, real=0.01 secs]

                29.655: [GC (Allocation Failure) [PSYoungGen: 56305K->15395K(66560K)] 74889K->33987K(197632K), 0.0139674 secs] [Times: user=0.03 sys=0.03, real=0.01 secs]

                35.931: [GC (Metadata GC Threshold) [PSYoungGen: 52659K->19268K(66560K)] 71251K->39216K(197632K), 0.0095867 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                35.940: [Full GC (Metadata GC Threshold) [PSYoungGen: 19268K->0K(66560K)] [ParOldGen: 19948K->37143K(94720K)] 39216K->37143K(161280K), [Metaspace: 20956K->20956K(1067008K)], 0.0605011 secs] [Times: user=0.14 sys=0.00, real=0.06 secs]

                45.363: [GC (Allocation Failure) [PSYoungGen: 46080K->7313K(67072K)] 83223K->44464K(161792K), 0.0033804 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                50.864: [GC (Allocation Failure) [PSYoungGen: 52369K->13474K(57856K)] 89520K->50634K(152576K), 0.0047487 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                61.093: [GC (Allocation Failure) [PSYoungGen: 57506K->20052K(64000K)] 94666K->57219K(158720K), 0.0083576 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                69.479: [GC (Allocation Failure) [PSYoungGen: 62036K->19812K(65536K)] 99203K->63579K(160256K), 0.0102430 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

                77.269: [GC (Allocation Failure) [PSYoungGen: 61225K->25589K(64000K)] 104993K->69613K(158720K), 0.0078168 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                84.418: [GC (Allocation Failure) [PSYoungGen: 63989K->18323K(56320K)] 108013K->75319K(151040K), 0.0124244 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                92.952: [GC (Allocation Failure) [PSYoungGen: 56211K->23301K(65024K)] 113207K->80296K(159744K), 0.0094024 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                101.924: [GC (Allocation Failure) [PSYoungGen: 59653K->28518K(66048K)] 116648K->85521K(160768K), 0.0083291 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                116.651: [GC (Allocation Failure) [PSYoungGen: 64358K->33255K(64000K)] 121361K->91539K(158720K), 0.0158377 secs] [Times: user=0.02 sys=0.05, real=0.02 secs]

                121.525: [GC (Allocation Failure) [PSYoungGen: 63975K->26069K(68608K)] 122259K->95817K(163328K), 0.0154230 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]

                125.256: [GC (Allocation Failure) [PSYoungGen: 56277K->25317K(68096K)] 126025K->100532K(162816K), 0.0109754 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]

                127.708: [GC (Allocation Failure) [PSYoungGen: 54904K->18115K(47616K)] 130119K->103585K(142336K), 0.0123351 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                127.720: [Full GC (Ergonomics) [PSYoungGen: 18115K->8177K(47616K)] [ParOldGen: 85469K->94299K(156672K)] 103585K->102476K(204288K), [Metaspace: 23050K->23050K(1071104K)], 0.1978434 secs] [Times: user=0.72 sys=0.00, real=0.20 secs]

                130.342: [GC (Allocation Failure) [PSYoungGen: 37349K->10018K(65536K)] 131649K->107319K(222208K), 0.0093659 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]

                132.791: [GC (Allocation Failure) [PSYoungGen: 38690K->9105K(37376K)] 135991K->111674K(194048K), 0.0051445 secs] [Times: user=0.05 sys=0.02, real=0.01 secs]

                135.242: [GC (Allocation Failure) [PSYoungGen: 37265K->4240K(65024K)] 139834K->115078K(221696K), 0.0057676 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                137.680: [GC (Allocation Failure) [PSYoungGen: 31888K->4272K(65536K)] 142726K->119113K(222208K), 0.0046895 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                140.604: [GC (Allocation Failure) [PSYoungGen: 31920K->4208K(65536K)] 146761K->123011K(222208K), 0.0047663 secs] [Times: user=0.05 sys=0.02, real=0.00 secs]

                145.108: [GC (Allocation Failure) [PSYoungGen: 31856K->4320K(32256K)] 150659K->127037K(188928K), 0.0042341 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                150.097: [GC (Allocation Failure) [PSYoungGen: 31968K->4352K(63488K)] 154685K->130968K(220160K), 0.0044873 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                153.104: [GC (Allocation Failure) [PSYoungGen: 32000K->8545K(36352K)] 158616K->135169K(193024K), 0.0066098 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                158.885: [GC (Allocation Failure) [PSYoungGen: 36193K->12290K(57344K)] 162817K->138922K(214016K), 0.0067832 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                164.617: [GC (Allocation Failure) [PSYoungGen: 39938K->16099K(44032K)] 166570K->142738K(200704K), 0.0075573 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                170.757: [GC (Allocation Failure) [PSYoungGen: 43747K->19940K(58368K)] 170386K->146587K(215040K), 0.0191865 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]

                176.804: [GC (Allocation Failure) [PSYoungGen: 46564K->20196K(59392K)] 173211K->150790K(216064K), 0.0101108 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                182.152: [GC (Allocation Failure) [PSYoungGen: 46820K->19780K(59392K)] 177414K->154368K(216064K), 0.0100827 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                188.486: [GC (Allocation Failure) [PSYoungGen: 45892K->19812K(59904K)] 180480K->158282K(216576K), 0.0093089 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                197.082: [GC (Allocation Failure) [PSYoungGen: 45924K->19524K(58880K)] 184394K->161869K(215552K), 0.0110855 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                201.534: [GC (Allocation Failure) [PSYoungGen: 45636K->22884K(59392K)] 187981K->165230K(216064K), 0.0115745 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                208.805: [GC (Allocation Failure) [PSYoungGen: 48996K->22868K(59392K)] 191342K->169080K(216064K), 0.0110878 secs] [Times: user=0.05 sys=0.02, real=0.01 secs]

                214.099: [GC (Allocation Failure) [PSYoungGen: 47956K->22692K(60416K)] 194168K->172650K(217088K), 0.0102075 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                214.110: [Full GC (Ergonomics) [PSYoungGen: 22692K->14725K(60416K)] [ParOldGen: 149957K->156601K(210944K)] 172650K->171327K(271360K), [Metaspace: 23368K->23368K(1071104K)], 0.2039168 secs] [Times: user=0.69 sys=0.00, real=0.20 secs]

                216.405: [GC (Allocation Failure) [PSYoungGen: 39813K->16803K(57344K)] 196415K->175934K(268288K), 0.0150768 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]

                218.507: [GC (Allocation Failure) [PSYoungGen: 41891K->15523K(40960K)] 201022K->179665K(251904K), 0.0111031 secs] [Times: user=0.05 sys=0.01, real=0.01 secs]

                220.726: [GC (Allocation Failure) [PSYoungGen: 40611K->13122K(55808K)] 204753K->182516K(266752K), 0.0336825 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]

                222.908: [GC (Allocation Failure) [PSYoungGen: 38210K->11186K(36352K)] 207604K->186391K(247296K), 0.0064386 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                225.041: [GC (Allocation Failure) [PSYoungGen: 36274K->7745K(56320K)] 211479K->190163K(267264K), 0.0098299 secs] [Times: user=0.03 sys=0.01, real=0.01 secs]

                227.204: [GC (Allocation Failure) [PSYoungGen: 32833K->4272K(56320K)] 215251K->193991K(267264K), 0.0125581 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                229.299: [GC (Allocation Failure) [PSYoungGen: 29360K->4208K(56832K)] 219079K->197513K(267776K), 0.0035849 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                231.427: [GC (Allocation Failure) [PSYoungGen: 29296K->4448K(29696K)] 222601K->201299K(240640K), 0.0080993 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                233.557: [GC (Allocation Failure) [PSYoungGen: 29536K->3776K(55296K)] 226387K->204245K(266240K), 0.0057061 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                235.675: [GC (Allocation Failure) [PSYoungGen: 28864K->3984K(29184K)] 229333K->208071K(240128K), 0.0056245 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                235.681: [Full GC (Ergonomics) [PSYoungGen: 3984K->0K(29184K)] [ParOldGen: 204087K->206569K(260096K)] 208071K->206569K(289280K), [Metaspace: 23376K->23376K(1071104K)], 0.1420228 secs] [Times: user=0.37 sys=0.02, real=0.14 secs]

                237.953: [GC (Allocation Failure) [PSYoungGen: 25088K->4288K(53248K)] 231657K->210858K(313344K), 0.0034838 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                240.113: [GC (Allocation Failure) [PSYoungGen: 29376K->4240K(29696K)] 235946K->214612K(289792K), 0.0036770 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                242.205: [GC (Allocation Failure) [PSYoungGen: 29328K->8001K(50688K)] 239700K->218373K(310784K), 0.0046693 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]

                244.328: [GC (Allocation Failure) [PSYoungGen: 33089K->11570K(36864K)] 243461K->221942K(296960K), 0.0103985 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]

                246.494: [GC (Allocation Failure) [PSYoungGen: 36658K->10882K(49152K)] 247030K->224856K(309248K), 0.0069070 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                248.647: [GC (Allocation Failure) [PSYoungGen: 35970K->11122K(36352K)] 249944K->228682K(296448K), 0.0091835 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                250.824: [GC (Allocation Failure) [PSYoungGen: 36210K->11330K(47104K)] 253770K->232469K(307200K), 0.0062808 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                252.987: [GC (Allocation Failure) [PSYoungGen: 36418K->11538K(36864K)] 257557K->236287K(296960K), 0.0089006 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]

                255.069: [GC (Allocation Failure) [PSYoungGen: 36626K->11506K(45568K)] 261375K->239897K(305664K), 0.0072053 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                257.173: [GC (Allocation Failure) [PSYoungGen: 36594K->11634K(36864K)] 264985K->243659K(296960K), 0.0070754 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                259.293: [GC (Allocation Failure) [PSYoungGen: 36722K->11602K(45056K)] 268747K->247214K(305152K), 0.0164710 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]

                261.414: [GC (Allocation Failure) [PSYoungGen: 36690K->7457K(32768K)] 272302K->250217K(292864K), 0.0093704 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                263.540: [GC (Allocation Failure) [PSYoungGen: 32545K->4064K(45056K)] 275305K->254005K(305152K), 0.0070926 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                265.678: [GC (Allocation Failure) [PSYoungGen: 29152K->4192K(45056K)] 279093K->257791K(305152K), 0.0058997 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                265.684: [Full GC (Ergonomics) [PSYoungGen: 4192K->0K(45056K)] [ParOldGen: 253598K->256786K(308224K)] 257791K->256786K(353280K), [Metaspace: 23386K->23386K(1071104K)], 0.1682450 secs] [Times: user=0.52 sys=0.03, real=0.17 secs]

                268.019: [GC (Allocation Failure) [PSYoungGen: 25088K->4432K(44032K)] 281874K->261219K(352256K), 0.0034418 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                270.517: [GC (Allocation Failure) [PSYoungGen: 29520K->8177K(33280K)] 286307K->264963K(341504K), 0.0045541 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                275.628: [GC (Allocation Failure) [PSYoungGen: 33265K->11762K(44032K)] 290051K->268548K(352256K), 0.0056168 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                279.220: [GC (Allocation Failure) [PSYoungGen: 36850K->15331K(44032K)] 293636K->272117K(352256K), 0.0070750 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                285.908: [GC (Allocation Failure) [PSYoungGen: 40419K->18916K(43520K)] 297205K->275702K(351744K), 0.0081665 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                290.277: [GC (Allocation Failure) [PSYoungGen: 41956K->22068K(45568K)] 298742K->278854K(353792K), 0.0092532 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                293.460: [GC (Allocation Failure) [PSYoungGen: 45108K->24853K(45056K)] 301894K->281647K(353280K), 0.0092280 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                297.243: [GC (Allocation Failure) [PSYoungGen: 44309K->27398K(48640K)] 301103K->284192K(356864K), 0.0132487 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                300.101: [GC (Allocation Failure) [PSYoungGen: 46854K->31030K(48640K)] 303648K->287824K(356864K), 0.0139671 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                302.074: [GC (Allocation Failure) [PSYoungGen: 46390K->32391K(52736K)] 303184K->289185K(360960K), 0.0091176 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                304.209: [GC (Allocation Failure) [PSYoungGen: 47751K->31030K(54272K)] 304545K->291555K(362496K), 0.0143395 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                305.969: [GC (Allocation Failure) [PSYoungGen: 43729K->25717K(56832K)] 304253K->293358K(365056K), 0.0138032 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                308.114: [GC (Allocation Failure) [PSYoungGen: 38517K->20644K(52736K)] 306158K->295377K(360960K), 0.0120359 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                309.843: [GC (Allocation Failure) [PSYoungGen: 33420K->15955K(29184K)] 308153K->297300K(337408K), 0.0145978 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]

                312.449: [GC (Allocation Failure) [PSYoungGen: 28755K->12338K(51200K)] 310100K->299167K(359424K), 0.0089588 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                315.447: [GC (Allocation Failure) [PSYoungGen: 25138K->9682K(22528K)] 311967K->300969K(330752K), 0.0070574 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                317.282: [GC (Allocation Failure) [PSYoungGen: 22482K->8049K(50688K)] 313769K->302987K(358912K), 0.0065083 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                319.272: [GC (Allocation Failure) [PSYoungGen: 20849K->6257K(51200K)] 315787K->304797K(359424K), 0.0090865 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                322.623: [GC (Allocation Failure) [PSYoungGen: 19057K->4464K(50176K)] 317597K->306566K(358400K), 0.0056988 secs] [Times: user=0.02 sys=0.03, real=0.01 secs]

                322.628: [Full GC (Ergonomics) [PSYoungGen: 4464K->0K(50176K)] [ParOldGen: 302102K->305259K(355328K)] 306566K->305259K(405504K), [Metaspace: 23393K->23393K(1071104K)], 0.1547819 secs] [Times: user=0.48 sys=0.00, real=0.16 secs]

                324.283: [GC (Allocation Failure) [PSYoungGen: 12800K->2688K(15872K)] 318059K->307948K(371200K), 0.0030035 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                325.819: [GC (Allocation Failure) [PSYoungGen: 15488K->3776K(49152K)] 320748K->309036K(404480K), 0.0035926 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                327.688: [GC (Allocation Failure) [PSYoungGen: 16576K->5793K(18944K)] 321836K->311052K(374272K), 0.0032674 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                331.391: [GC (Allocation Failure) [PSYoungGen: 18593K->7569K(44544K)] 323852K->312829K(399872K), 0.0063538 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]

                333.195: [GC (Allocation Failure) [PSYoungGen: 20369K->9634K(22528K)] 325629K->314893K(377856K), 0.0055116 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                334.890: [GC (Allocation Failure) [PSYoungGen: 22434K->11586K(40960K)] 327693K->316846K(396288K), 0.0061749 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                339.327: [GC (Allocation Failure) [PSYoungGen: 24341K->13186K(26112K)] 329600K->318446K(381440K), 0.0056949 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]

                341.937: [GC (Allocation Failure) [PSYoungGen: 25986K->15107K(40960K)] 331246K->320366K(396288K), 0.0072376 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                343.569: [GC (Allocation Failure) [PSYoungGen: 27907K->17043K(41472K)] 333166K->322303K(396800K), 0.0074683 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

                345.227: [GC (Allocation Failure) [PSYoungGen: 29843K->19076K(40448K)] 335103K->324335K(395776K), 0.0073480 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]

                348.349: [GC (Allocation Failure) [PSYoungGen: 30802K->20212K(41472K)] 336062K->325471K(396800K), 0.0253761 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

                350.763: [GC (Allocation Failure) [PSYoungGen: 31965K->17923K(42496K)] 337224K->326838K(397824K), 0.0194671 secs] [Times: user=0.03 sys=0.02, real=0.02 secs]

                352.459: [GC (Allocation Failure) [PSYoungGen: 29699K->16707K(28672K)] 338614K->329264K(384000K), 0.0078481 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                354.288: [GC (Allocation Failure) [PSYoungGen: 28483K->14451K(38912K)] 341040K->330705K(394240K), 0.0100247 secs] [Times: user=0.00 sys=0.02, real=0.01 secs]

                355.722: [GC (Allocation Failure) [PSYoungGen: 26227K->12162K(24064K)] 342481K->331987K(379392K), 0.0087294 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                357.160: [GC (Allocation Failure) [PSYoungGen: 23938K->10834K(37376K)] 343763K->334293K(392704K), 0.0124772 secs] [Times: user=0.03 sys=0.02, real=0.01 secs]

                358.582: [GC (Allocation Failure) [PSYoungGen: 22610K->9105K(20992K)] 346069K->335839K(376320K), 0.0073579 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

                359.972: [GC (Allocation Failure) [PSYoungGen: 20881K->7169K(37888K)] 347615K->337328K(393216K), 0.0102177 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                363.970: [GC (Allocation Failure) [PSYoungGen: 18945K->5793K(37888K)] 349104K->339218K(393216K), 0.0057125 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                365.533: [GC (Allocation Failure) [PSYoungGen: 17569K->3936K(37888K)] 350994K->340804K(393216K), 0.0049129 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                366.651: [GC (Allocation Failure) [PSYoungGen: 15635K->2208K(37888K)] 352502K->342333K(393216K), 0.0054696 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

                367.630: [GC (Allocation Failure) [PSYoungGen: 13984K->1936K(37888K)] 354109K->343815K(393216K), 0.0028364 secs] [Times: user=0.06 sys=0.00, real=0.00 secs]

                368.648: [GC (Allocation Failure) [PSYoungGen: 13712K->2560K(14848K)] 355591K->346072K(370176K), 0.0039404 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                369.667: [GC (Allocation Failure) [PSYoungGen: 14305K->2416K(36352K)] 357817K->347617K(391680K), 0.0037561 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                370.677: [GC (Allocation Failure) [PSYoungGen: 14130K->2176K(14336K)] 359331K->349098K(369664K), 0.0054005 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                371.644: [GC (Allocation Failure) [PSYoungGen: 13952K->1888K(34816K)] 360874K->350563K(390144K), 0.0039212 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                372.623: [GC (Allocation Failure) [PSYoungGen: 13664K->2480K(14336K)] 362339K->352804K(369664K), 0.0036386 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                372.627: [Full GC (Ergonomics) [PSYoungGen: 2480K->0K(14336K)] [ParOldGen: 350323K->351321K(397312K)] 352804K->351321K(411648K), [Metaspace: 23409K->23409K(1071104K)], 0.1756339 secs] [Times: user=0.56 sys=0.00, real=0.17 secs]

                373.768: [GC (Allocation Failure) [PSYoungGen: 11719K->2448K(33280K)] 363041K->353770K(430592K), 0.0035548 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                374.753: [GC (Allocation Failure) [PSYoungGen: 14224K->2208K(14336K)] 365546K->355271K(411648K), 0.0038537 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                375.951: [GC (Allocation Failure) [PSYoungGen: 13984K->1904K(30720K)] 367047K->356704K(428032K), 0.0045295 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

                Heap

                PSYoungGen      total 30720K, used 11565K [0x0000000780180000, 0x0000000783400000, 0x00000007c0000000)

                  eden space 11776K, 82% used [0x0000000780180000,0x0000000780aef638,0x0000000780d00000)

                  from space 18944K, 10% used [0x0000000782180000,0x000000078235c1a0,0x0000000783400000)

                  to  space 19968K, 0% used [0x0000000780d00000,0x0000000780d00000,0x0000000782080000)

                ParOldGen      total 397312K, used 354800K [0x0000000700400000, 0x0000000718800000, 0x0000000780180000)

                  object space 397312K, 89% used [0x0000000700400000,0x0000000715e7c1d8,0x0000000718800000)

                Metaspace      used 23438K, capacity 23852K, committed 24064K, reserved 1071104K

                  class space    used 2917K, capacity 3019K, committed 3072K, reserved 1048576K

                • 6. Re: How come this simplistic test generate OOM behavior?
                  alwu-Oracle

                  Hi,

                   

                  Thanks for the traces. Let's do one experiment and see if the behavior changes. In your testTransactionHandlingViaJdbcTransactions code,

                  can you please take out the construction of oracle1, oracle2, oracle3, and model1, model2, model3. We can do the construction somewhere else, just once. Also, please take out model?.close and oracle?.displose. Basically, that method does nothing but read data, write data, and commit.


                  This way, we separate out from the equation variables like connection and model level operations.

                  If you still see memory issues after this change, please either file a SR or send me an email with

                  the simplified test case.


                  Thanks,


                  Zhe Wu

                  (alan dot wu at oracle dot com)

                  • 7. Re: How come this simplistic test generate OOM behavior?
                    jhberges

                    Hello again!

                     

                    Yes, moving the connection/model initialization out of the outer for-loop removes the memory leak.

                    I also observe the same if I remove interaction with the Model instances (i.e no reading or writing) - then the GC manages well, and the memory baseline is quite flat.

                    withouth-conn-pooling.png

                     

                    However, this doesn't help us much since we require connection pooling and connection-level transactional demarcations.

                    This is due to the access being made from an Apache Camel app, where transactions are handled by Spring (over a javax.sql.DataSource).

                    This app will need to scale horizontally dynamically so we cannot have global facade object, and certainly not ones backed by a single connection.

                     

                    Is the correct approach from here to raise an issue via my client perhaps? (me being a consultant/contractor)

                    • 8. Re: How come this simplistic test generate OOM behavior?
                      alwu-Oracle

                      Hi,

                       

                      OK. Please ask your client to raise an SR. Once you have the SR #, please send it to me. SR is the official process.

                       

                      In the meantime, we can do a few more experiments to further scope down the issues. I am happy to see that model level

                      operations did not cause any memory leaks. In your original code, if testTransactionHandlingViaJdbcTransactions

                      does not take Oracle from OraclePool, but rather create a new JDBC connection, followed by a new

                      Oracle and a set of model level operations, ended with a dispose of Oracle and close of the JDBC connection,

                      do you see a different behavior?


                      Thanks,


                      Zhe Wu

                      • 9. Re: Re: How come this simplistic test generate OOM behavior?
                        jhberges

                        Hello.

                         

                        The issue has been communicated with Oracle Norway (at Lysaker, Oslo).

                         

                        The change you proposed, i.e (pseudo):

                          for (..) {

                              try (OracleConnection con = datasource.getConnection()) {

                                  Oracle oracle = new Oracle(con);

                                  Model model = ModelOracleSem.createOracleSemModel(oracle, OracleMetadataDaoITCase.INTEGRATION_TEST_MODEL);

                                  ResIterator iterator = model.listSubjects();

                                  ....

                                  iterator.close();

                                  model.close();

                                 oracle.dispose();

                              } finally {

                                 con.close();

                              }

                           }

                         

                        Have the same effect as using OraclePool.

                        • 10. Re: How come this simplistic test generate OOM behavior?
                          alwu-Oracle

                          Thanks. We are trying to reproduce locally.

                           

                          Zhe Wu

                          • 11. Re: How come this simplistic test generate OOM behavior?
                            alwu-Oracle

                            Hi,

                             

                            We did reproduce the problem locally. Thanks again for the test case!

                             

                            Here is a simple setting that seems to help quite a bit.

                            After

                                    oracleDataSource = new OracleDataSource();

                             

                            can you please add the following line

                                    oracleDataSource.setConnectionCachingEnabled(true);


                            Do you still see the OOM?


                            Thanks,


                            Zhe Wu & Miriam Mecate

                            • 12. Re: Re: How come this simplistic test generate OOM behavior?
                              jhberges

                              Hi, and thanks for the update.

                               

                              Setting this property seems to reduce the inclination of the leak-rate, but doesn't eliminate it (see graph).

                              Seems to occupy 40 megs in 10 minutes, as opposed to 200 megs in 3 minutes without it.

                               

                              The graph is from a run with 10.000 iterations (with -Xmx70m), pausing at the end in to see if the GC would catch up and stabilize.

                              Looking at the "Memory" tab, it's clear that it's the "OldGen" that gets stuffed :-/

                               

                              Ending GC trace:

                              Heap

                              PSYoungGen      total 21504K, used 13226K [0x00000000fe900000, 0x0000000100000000, 0x0000000100000000)

                                eden space 19456K, 67% used [0x00000000fe900000,0x00000000ff5eaac8,0x00000000ffc00000)

                                from space 2048K, 0% used [0x00000000ffc00000,0x00000000ffc00000,0x00000000ffe00000)

                                to   space 2048K, 0% used [0x00000000ffe00000,0x00000000ffe00000,0x0000000100000000)

                              ParOldGen       total 48128K, used 47981K [0x00000000fba00000, 0x00000000fe900000, 0x00000000fe900000)

                                object space 48128K, 99% used [0x00000000fba00000,0x00000000fe8db470,0x00000000fe900000)

                              Metaspace       used 22955K, capacity 23294K, committed 23808K, reserved 1071104K

                                class space    used 2917K, capacity 3004K, committed 3072K, reserved 1048576K

                               

                              10k_ConnectionCachingEnabled_Xmx70m-memory.png

                              10k_ConnectionCachingEnabled_Xmx70m-heap_gc_and_pools.png

                              10k_ConnectionCachingEnabled_Xmx70m-GC-marksweep.png

                              • 13. Re: How come this simplistic test generate OOM behavior?
                                alwu-Oracle

                                Hi,

                                 

                                We found a problem (where TBoxFactory was not letting go of references to GraphOracleSem objects). It has been fixed.

                                Could you please file an SR so that we can pass along the fix?

                                 

                                Thanks,

                                 

                                Zhe Wu & Miriam Mecate

                                • 14. Re: Re: How come this simplistic test generate OOM behavior?
                                  jhberges

                                  Hi - Great news!

                                   

                                  SR is filed as 3-11320855021

                                   

                                  BR. Jan-Helge

                                  1 2 Previous Next