Using garbagecat for continuous garbage log monitoring

[Norbo11]

Hi, I was wondering how possible it would be for me to use garbagecat as a solution to monitor GC statistics in real-time.

I have a web server running, which logs GC stats to a log file. I want to be able to get garbagecat output programmatically without invoking the command line. I have therefore imported it into my project, and am currently doing something like this:

        GcManager gc = new GcManager();

        Date date = new Date(2019, 01, 29);

        File file = new File("C:\\Users\\Norbo11\\Desktop\\gc.log");
        file = gc.preprocess(file, date);
        gc.store(file, false);
        Jvm jvm = new Jvm("", date);

        JvmRun jvmRun = gc.getJvmRun(jvm, Constants.DEFAULT_BOTTLENECK_THROUGHPUT_THRESHOLD);

        System.out.println(jvmRun.getBlockingEventCount());
        System.out.println(jvmRun.getGcThroughput());
        System.out.println(jvmRun.getJvmRunDuration());
        System.out.println(jvmRun.getUnidentifiedLogLines().size());

This is currently outputting the statistics that I would expect. However, it seems that this is a bit unsuitable, as it consumes an entire log file. I would ideally like to tail the log file, and every 5 seconds update my statistics.

Would this be possible with garbagecat? I'm happy to write my own logic for keeping track of the statistics, but I wanted to leverage this library's parsing capabilities. Is there a lower-level class than JvmRun that would expose the properties that I need?

[Norbo11]

Update: I was able to get out the individual GC events using this code:

        Field f = gc.getClass().getDeclaredField("jvmDao");
        f.setAccessible(true);
        JvmDao dao = (JvmDao) f.get(gc);

        for (BlockingEvent e : dao.getBlockingEvents()) {
            System.out.println(e.getName());
            System.out.println(e.getTimestamp());
            System.out.println(e.getDuration());
        }

Unfortunately the jvmDao field is private and doesn't have a getter, so I had to use reflection.

I am still wondering if there is an easier way of doing this, so some help would be appreciated.

[Norbo11]

After some more experimentation, the above approach looked promising. I am now trying to monitor the heap size changes along with the events.

The first thing I did was something like:

            if (event instanceof YoungData) {
                YoungData e = (YoungData) event;
                System.out.println(e.getYoungOccupancyInit());
                System.out.println(e.getYoungOccupancyEnd());
                System.out.println(e.getYoungSpace());
            }

            else if (event instanceof OldData) {
                OldData e = (OldData) event;
                System.out.println(e.getOldOccupancyInit());
                System.out.println(e.getOldOccupancyEnd());
                System.out.println(e.getOldSpace());
            }

            else if (event instanceof CombinedData) {
                CombinedData e = (CombinedData) event;
                System.out.print(" " + e.getCombinedOccupancyInit());
                System.out.println(e.getCombinedOccupancyEnd());
                System.out.println(e.getCombinedSpace());
            }

            else if (event instanceof PermData) {
                PermData e = (PermData) event;
                System.out.println(e.getPermOccupancyInit());
                System.out.println(e.getPermOccupancyEnd());
                System.out.println(e.getPermSpace());
            }

            else if (event instanceof TimesData) {
                TimesData e = (TimesData) event;
                System.out.println(e.getTimeReal());
                System.out.println(e.getTimeUser());
                System.out.println(e.getParallelism());
            }

However, all of these values returned 0.

After investigating some more, I realised that the getBlockingEvents() function queries the HSQL database used to store events. However, the code responsible for this only seems to populate the event name, duration and log entry fields when re-creating the event object using JdkUtil.hydrateBlockingEvent. Unfortunately this means that the heap-usage data is 0.

I then realised that some of this information is in fact being stored inside HSQL, and so I tried to rectify the issue with something like this:

 public synchronized List<BlockingEvent> getBlockingEvents(Connection connection) throws Throwable {
           ...setup connection

            sql.append("select time_stamp, event_name, "
                    + "duration, young_space, old_space, combined_space, perm_space, young_occupancy_init, "
                    + "old_occupancy_init, combined_occupancy_init, perm_occupancy_init, log_entry "
                    + "from blocking_event "
                    + "order by time_stamp asc, id asc");

            final int TIME_STAMP_INDEX = 1;
            final int EVENT_NAME_INDEX = 2;
            final int DURATION_INDEX = 3;
            final int YOUNG_SPACE_INDEX = 4;
            final int OLD_SPACE_INDEX = 5;
            final int COMBINED_SPACE_INDEX = 6;
            final int PERM_SPACE_INDEX = 7;
            final int YOUNG_OCCUPANCY_INIT_INDEX = 8;
            final int OLD_OCCUPANCY_INIT_INDEX = 9;
            final int COMBINED_OCCUPANCY_INIT_INDEX = 10;
            final int PERM_OCCUPANCY_INIT_INDEX = 11;
            final int LOG_ENTRY_INDEX = 12;

            rs = statement.executeQuery(sql.toString());
            while (rs.next()) {
                JdkUtil.LogEventType eventType = JdkUtil.determineEventType(rs.getString(2));

                BlockingEvent event = JdkUtil.hydrateBlockingEvent(eventType, rs.getString(4), rs.getLong(1),
                        rs.getInt(3));

                if (event instanceof UnifiedG1YoungPauseEvent) {
                    UnifiedG1YoungPauseEvent e = (UnifiedG1YoungPauseEvent) event;
                    Field f1 = e.getClass().getDeclaredField("combinedBegin");
                    f1.setAccessible(true);
                    f1.set(event, rs.getInt(COMBINED_OCCUPANCY_INIT_INDEX));

                    f1 = e.getClass().getDeclaredField("combinedAllocation");
                    f1.setAccessible(true);
                    f1.set(event, rs.getInt(COMBINED_SPACE_INDEX));
                }

                ... Repeat for all types 

                events.add(event);
            }
       ...finally block, etc

       return events;

This populates the combinedBegin and combinedAllocation fields of the reconstructed UnifiedG1YoungPauseEvent, such that they can be available when I query them (in code extract 1). Of course, reflection is definitely not the way to go here, but I was using it as a proof-of-concept and following the same idea as in the above post.

The problem is that combinedEnd cannot be populated as it is currently not being inserted into the database.

I then tried to skip accessing the database by simply using the blockedBatch object that aggregates all events, but this is cleared every 100 events and so it doesn't work for me.

My last option is to modify the entire codebase to store this data and properly reconstruct every event upon calling getBlockingEvents(). I don't have time to do this right now, but it would be an extremely helpful change to allow people like me to get the data they want.

Again, if I am misunderstanding anything about this library, please point me in the right direction.

[mgm3746]

Hi,

I'm sorry for the delay. Thank you for explaining what you are trying to do. I will circle back to this after I finish JDK11 updates, as it's an interesting use case.

[mgm3746]

Hi, the hsqldb was recently removed and replaced by the Java Stream API. I think you should be able to achieve what you are trying to do much easier now.