mgm3746 / garbagecat Goto Github PK

What steps will reproduce the problem?
1. parse attached G1GC log
2.
3.

What is the expected output? What do you see instead?

I expect parse to succeed, instead I see this:

Exception in thread "main" java.lang.NumberFormatException: For input string: 
"M"
        at java.lang.NumberFormatException.forInputString(NumberFormatException.java:48)
        at java.lang.Integer.parseInt(Integer.java:449)
        at java.lang.Integer.parseInt(Integer.java:499)
        at org.eclipselabs.garbagecat.domain.jdk.G1CleanupEvent.<init>(G1CleanupEvent.java:109)



What version of the product are you using? On what operating system?
I built from trunk.  Windows.

Please provide any additional information below.

The G1CleanupEvent needs to skip the 'K' and 'M" identifiers.  Was:
    public G1CleanupEvent(String logEntry) {
        this.logEntry = logEntry;
        Matcher matcher = pattern.matcher(logEntry);
        if (matcher.find()) {
            timestamp = JdkMath.convertSecsToMillis(matcher.group(12)).longValue();
            combined = Integer.parseInt(matcher.group(13)) * 1024;
            combinedEnd = Integer.parseInt(matcher.group(14)) * 1024;
            combinedAvailable = Integer.parseInt(matcher.group(15)) * 1024;
            duration = JdkMath.convertSecsToMillis(matcher.group(16)).intValue();
        }
    }

Change (The code also needs to take K versus M into consideration, my 'patch' 
does not do this:

    public G1CleanupEvent(String logEntry) {
        this.logEntry = logEntry;
        Matcher matcher = pattern.matcher(logEntry);
        if (matcher.find()) {
            timestamp = JdkMath.convertSecsToMillis(matcher.group(12)).longValue();
            combined = Integer.parseInt(matcher.group(13)) * 1024;
            combinedEnd = Integer.parseInt(matcher.group(15)) * 1024;
            combinedAvailable = Integer.parseInt(matcher.group(17)) * 1024;
            duration = JdkMath.convertSecsToMillis(matcher.group(19)).intValue();
        }
    }

With later versions of the JDK it appears the -XX:+PrintGCDateStamps option 
prefixes the logging with a datestamp instead of replacing the timestamp. For 
example:

2011-03-22T06:04:39.356-0700: 18917.821: [GC [1 CMS-initial-mark: 
11191244K(22369664K)] 11283368K(25083584K), 0.5119906 secs] [Times: user=0.37 
sys=0.15, real=0.51 secs]

Allow handling without specifying the JVM start date.

v 1.0.0
This is not a bug. Small improvement
In  the GCUtil.dateDiff()in Calendar.getInstance() the Calendar object is being 
created in each call. And this happens very often.
I propose simplified version of dateDiff() method as follows

--------------------------------------------

public static final long dateDiff(Date start, Date end) {
        return end.getTime()-start.getTime();
    }

-------------------------------------------------------

Add a check to ensure all source lines are not longer than 120 characters.

Handling using -XX:+PrintGCDetails with the G1 collector, which results in very 
verbose output. For example:

0.807: [GC pause (young), 0.00290200 secs]
   [Parallel Time:   2.7 ms]
      [GC Worker Start Time (ms):  807.5  807.8  807.8  810.1]
      [Update RS (ms):  0.1  0.1  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.1]
         [Processed Buffers : 2 1 0 0
          Sum: 3, Avg: 0, Min: 0, Max: 2]
      [Ext Root Scanning (ms):  0.6  0.3  0.4  0.0
       Avg:   0.3, Min:   0.0, Max:   0.6]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan RS (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Object Copy (ms):  0.5  0.5  0.5  0.0
       Avg:   0.4, Min:   0.0, Max:   0.5]
      [Termination (ms):  1.4  1.5  1.4  0.0
       Avg:   1.1, Min:   0.0, Max:   1.5]
         [Termination Attempts : 1 1 1 1
          Sum: 4, Avg: 1, Min: 1, Max: 1]
      [GC Worker End Time (ms):  810.1  810.2  810.1  810.1]
      [Other:   0.9 ms]
   [Clear CT:   0.1 ms]
   [Other:   0.1 ms]
      [Choose CSet:   0.0 ms]
   [ 29M->2589K(59M)]

Report object creation and promotion rates (e.g. in KB/sec).

This could be gauged similarly to throughput and set threshold levels to 
indicate specific periods of trouble. 

It may be entirely redundant to throughput data; however, it is another metric 
to consider.

Report observed NewRatio, as generally it should fall within a certain range 
for best gc performance.

Preprocessing will not handle a combined CmsConcurrentEvent and 
ApplicationStoppedTimeEvent followed by an ApplicationConcurrentTimeEvent, and 
on the 3rd line the times data for the CmsConcurrentEvent.

For example, these 3 lines:

324217.024: [CMS-concurrent-abortable-preclean: 0.015/0.073 secs]Total time for 
which application threads were stopped: 0.0125060 seconds
Application time: 0.0001900 seconds
 [Times: user=0.05 sys=0.00, real=0.08 secs]

Will be preprocessed into these 2 lines:
Total time for which application threads were stopped: 0.0125060 seconds
324217.024: [CMS-concurrent-abortable-preclean: 0.015/0.073 secs]Application 
time: 0.0001900 seconds
 [Times: user=0.05 sys=0.00, real=0.08 secs]

Resulting in the times data not being associated with the CmsConcurrent event 
and stranded on a line and reported as an unidentified log line.

Report if class unloading not happening (CMS_REMARK instead of 
CMS_REMARK_WITH_CLASS_UNLOADING).

Handle ParalleScavengeEvent split across multiple lines due to 
-XX:+PrintTenuringDistribution. For example:

18.392: [GC
Desired survivor size 497025024 bytes, new threshold 7 (max 15)
 [PSYoungGen: 970752K->104301K(1456128K)] 970752K->104301K(3708928K), 0.1992940 secs] [Times: user=0.68 sys=0.05, real=0.20 secs]

The JVM can log GC events with the date-time rather than a timestamp since the 
JVM started if you specify the -XX:+PrintGCDateStamps option rather than 
-XX:+PrintGCTimeStamps, which looks like

2012-04-24T22:01:01.703-0500: [GC [PSYoungGen: 786432K->100769K(917504K)] 
849627K->163964K(3014656K), 0.1332500 secs] [Times: user=0.71 sys=0.05, 
real=0.13 secs]


Garbage Cat should be able to handle these, as well as logs with both options 
which look like

2012-04-24T22:01:01.703-0500: 10.153: [GC [PSYoungGen: 
786432K->100769K(917504K)] 849627K->163964K(3014656K), 0.1332500 secs] [Times: 
user=0.71 sys=0.05, real=0.13 secs]

If the GC log is very large (hundreds of MBs), it will take a very long time 
(hours) to parse.

Handle ParallelOldCompactingEvent logging split across 2 lines due to the 
garbage collection overhead limit being reached:

52767.809: [Full GC [PSYoungGen: 109294K->94333K(184960K)] [ParOldGen: 
1307971K->1307412K(1310720K)] 1417265K->1401746K(1495680K) [PSPermGen: 
113654K->113646K(196608K)]        GC time is exceeding GCTimeLimit of 98%
, 9.6599230 secs]

Incremental mode (iCMS) is useful on systems with 1-2 processors that cannot 
dedicate 1-2 processors to manage the different concurrent phases.

What steps will reproduce the problem?
1. Run the command
java -jar garbagecat-1.0.1.jar gc.log 


What is the expected output? What do you see instead?
I dont see any output.

What version of the product are you using? On what operating system?
Tried on both Windows XP or RHEL Linux. 
Tried on 1.6 and 1.7 JREs.

Please provide any additional information below.
Attached is a sample gc.log

Thanks.

The javadoc comment implies that using large pages will help prevent 
fragmentation; however, it will not prevent the type of fragmentation at issue 
here, which is jvm fragmentation, not address space fragmentation.

The patch for Issue 25 (Megabytes in reported sizes) switched from SIZE_MB to 
SIZE_JDK7 but only changed the parsing code for G1YoungPause. The other G1GC 
events need to handle the extra regex groups for K/M.

For example:

2014-01-06T06:24:16.032-0500: [Full GC [CMS: 842440K->790888K(1884160K), 
4.3945870 secs] 972654K->790888K(2075904K), [CMS Perm : 
66698K->65935K(66932K)], 4.3951190 secs] [Times: user=4.39 sys=0.00, real=4.39 
secs]

Flag issues where there are many full collections in a row and only young space 
is collected, old gen is filled up. It's a precursor to OOME.

Handle -XX:+PrintHeapAtGC logging where full collection enumerations are more 
than a single digit. For example "full 13" in the first line below:

Heap after GC invocations=312 (full 13):
 PSYoungGen      total 429248K, used 0K [0xffffffff4ec00000, 0xffffffff6e400000, 0xffffffff6e400000)
  eden space 344896K, 0% used [0xffffffff4ec00000,0xffffffff4ec00000,0xffffffff63cd0000)
  from space 84352K, 0% used [0xffffffff63cd0000,0xffffffff63cd0000,0xffffffff68f30000)
  to   space 82048K, 0% used [0xffffffff693e0000,0xffffffff693e0000,0xffffffff6e400000)
 PSOldGen        total 1028096K, used 241443K [0xffffffff10000000, 0xffffffff4ec00000, 0xffffffff4ec00000)
  object space 1028096K, 23% used [0xffffffff10000000,0xffffffff1ebc8f28,0xffffffff4ec00000)
 PSPermGen       total 262144K, used 126669K [0xfffffffef0000000, 0xffffffff00000000, 0xffffffff10000000)
  object space 262144K, 48% used [0xfffffffef0000000,0xfffffffef7bb37d8,0xffffffff00000000)
}

Expand PrintHeapAtGc preprocessing to handle the following PrintHeapAtGc 
logging with "tenured generation", "the space", "compacting perm gen", and "No 
shared spaces configured." (Class Data Sharing) output:

62248.693: [ParNew: 284666K->8619K(309696K), 0.0175680 secs] 
776295K->500656K(1014208K)Heap after gc invocations=371:
 par new generation   total 309696K, used 8619K [0x00002aab1aab0000, 0x00002aab2fab0000, 0x00002aab2fab0000)
  eden space 275328K,   0% used [0x00002aab1aab0000, 0x00002aab1aab0000, 0x00002aab2b790000)
  from space 34368K,  25% used [0x00002aab2d920000, 0x00002aab2e18adb8, 0x00002aab2fab0000)
  to   space 34368K,   0% used [0x00002aab2b790000, 0x00002aab2b790000, 0x00002aab2d920000)
 tenured generation   total 704512K, used 492037K [0x00002aab2fab0000, 0x00002aab5aab0000, 0x00002aab7aab0000)
   the space 704512K,  69% used [0x00002aab2fab0000, 0x00002aab4db314f8, 0x00002aab4db31600, 0x00002aab5aab0000)
 compacting perm gen  total 262144K, used 180122K [0x00002aab7aab0000, 0x00002aab8aab0000, 0x00002aab8aab0000)
   the space 262144K,  68% used [0x00002aab7aab0000, 0x00002aab85a96ab8, 0x00002aab85a96c00, 0x00002aab8aab0000)
No shared spaces configured.
} 
, 0.0178110 secs]


Preprocessed:
62248.693: [GC 62248.693: [ParNew: 284666K->8619K(309696K), 0.0175680 secs] 
776295K->500656K(1014208K), 0.0178110 secs]

Handle this logging:

3970.585: [GC[YG occupancy: 153169 K (471872 K)]3970.585: [Rescan (parallel) , 
0.0205830 secs]3970.606: [weak refs processing, 0.0125640 secs]3970.619: [scrub 
string table, 0.0057870 secs] [1 CMS-remark: 2822060K(5619712K)] 
2975230K(6091584K), 0.0402070 secs] [Times: user=0.15 sys=0.00, real=0.04 secs]

What steps will reproduce the problem?
1. On a 64-bit JDK run a program that produces heap sizes greater than 100GB.
2. Parse the logs with Garbage Cat.
3. Note the many unknown log entries.


What is the expected output? What do you see instead?
I expect to see these entries appropriately parsed.


What version of the product are you using? On what operating system?
I'm running Garbage Cat 1.0.1 & trunk against logs produced with:
-XX:+PrintGC
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-Xloggc:gc.log

JDK:
java version "1.6.0_22"
Java(TM) SE Runtime Environment (build 1.6.0_22-b04)
Java HotSpot(TM) 64-Bit Server VM (build 17.1-b03, mixed mode)


Please provide any additional information below.
Lines like the following are failing to parse:
1006.751: [GC [PSYoungGen: 61139904K->20643840K(67413056K)] 
119561147K->80396669K(129092672K), 3.8993460 secs] [Times: user=66.40 sys=3.73, 
real=3.89 secs] 

Add the ability to recognize thread data name with a forward slash when 
identifying thread dumps for preprocessing. For example:

"/com/my/MyThread-10" prio=1 tid=0x093c3318 nid=0x7c5e runnable 
[0x49fdd000..0x49fdde30]

This is not a bug, just proposition of simplification of getDatePlusTimestamp() 
method.

Proposed version of method should work faster and does not create the Calendar 
objects in each call

-------------------------------------
public static final Date getDatePlusTimestamp(Date start, long timestamp) {

        long milis = start.getTime() + timestamp ;
        return new Date(milis) ;

    }
-------------------------------------

Handle this logging:
 CMS: abort preclean due to time 2011-03-22T06:04:58.895-0700: 18937.361: [CMS-concurrent-abortable-preclean: 5.271/5.509 secs] [Times: user=7.73 sys=0.07, real=5.51 secs]

Should be identified as CMS_CONCURRENT_EVENT.

Preprocess datestamp prefixes beyond the initial datestamp. 

For example:
2013-12-09T16:18:17.813+0000: 13.086: [GC2013-12-09T16:18:17.813+0000: 13.086: 
[ParNew: 272640K->33532K(306688K), 0.0381419 secs] 272640K->33532K(1014528K), 
0.0383306 secs] [Times: user=0.11 sys=0.02, real=0.04 secs]

Should be preprocessed as follows:
13.086: [GC 13.086: [ParNew: 272640K->33532K(306688K), 0.0381419 secs] 
272640K->33532K(1014528K), 0.0383306 secs] [Times: user=0.11 sys=0.02, 
real=0.04 secs]

ParNewCmsConcurrentPreprocessAction and 
CmsConcurrentModeFailurePreprocessAction deal with 
"CMS-concurrent-abortable-preclean" events that can occur within other events. 
DateStampPrefixPreprocessAction removes the datestamps which can occur along 
with timestamps.


Unfortunately they do not work together, if a CMS-concurrent-abortable-preclean 
occurs with -XX:+PrintGCDateStamps in use. This is because the datestamp occurs 
prior to the second event, in the middle of the line. For example:


2012-09-16T21:05:49.639-0400: 523257.353: [GC 523257.353: 
[ParNew2012-09-16T21:05:49.689-0400: 523257.402: 
[CMS-concurrent-abortable-preclean: 0.249/1.880 secs] [Times: user=0.55 
sys=0.02, real=1.88 secs]
: 34950K->1132K(38336K), 0.1511615 secs] 1252386K->1218568K(5546688K), 
0.1515215 secs] [Times: user=0.24 sys=0.00, real=0.15 secs]

Handle what looks like JDK7 version of CMS_REMARK_WITH_CLASS_UNLOADING:

75.500: [GC[YG occupancy: 163958 K (306688 K)]75.500: [Rescan (parallel) , 
0.0491823 secs]75.549: [weak refs processing, 0.0088472 secs]75.558: [class 
unloading, 0.0049468 secs]75.563: [scrub symbol table, 0.0034342 secs]75.566: 
[scrub string table, 0.0005542 secs] [1 CMS-remark: 378031K(707840K)] 
541989K(1014528K), 0.0687411 secs] [Times: user=0.13 sys=0.00, real=0.07 secs]

Replace \n with bufferedWriter.newline() or 
System.getProperty("line.separator").

OracleJDK 1.7 update 55

2014-07-08T13:25:56.259+0100: 196.082: [GC2014-07-08T13:25:56.259+0100: 
196.082: [ParNew: 471871K->35576K(471872K), 0.2695773 secs] 
586079K->162457K(3093312K), 0.2699776 secs] [Times: user=0.48 sys=0.00, 
real=0.27 secs]

Change HSQLDB from file to memory-only database.

The logic that throws a TimeWarpException when GC events overlap does not work 
correctly when an event has a duration of less than 1ms. Short events can be 
followed by another GC event with the same timestamp due to it's milisecond 
accuracy, for example a quickly failing normal GC followed by the Full GC it 
triggers.

Running garbagecat on the following log fragment reproduces the problem:

3010778.296: [GC 3010778.296: [ParNew: 337824K->32173K(368640K), 0.0803880 
secs] 806117K->500466K(1187840K), 0.0805980 secs]
3010786.012: [GC 3010786.012: [ParNew: 356703K->356703K(368640K), 0.0000190 
secs] 824995K->824995K(1187840K), 0.0001460 secs]
3010786.012: [Full GC 3010786.012: [Tenured: 468292K->482213K(819200K), 
1.9920590 secs] 824995K->482213K(1187840K), [Perm : 123092K->122684K(262144K)], 
1.9924510 secs]

Add the ability to enforce coding standards when building. The build should 
fail if certain coding standards are not met.

Log lines that have "GC time would exceed GCTimeLimit" and "GC time is 
exceeding GCTimeLimit" messages are not being recognized. Here is a sample:

25207.640: [Full GC [PSYoungGen: 1762560K->89633K(2185856K)] [ParOldGen: 
2971644K->2971645K(2971648K)] 4734204K->3061278K(5157504K) [PSPermGen: 
309869K->309857K(310208K)]      GC time would exceed GCTimeLimit of 70%
, 8.9429330 secs] [Times: user=109.45 sys=0.30, real=8.94 secs] 

The message itself seems to be mal-formed, perhaps there is a bug in JDK (using 
1.6.0_21_x64). We run with -XX:GCTimeLimit=70 and -XX:GCHeapFreeLimit=40 
options.

The attached zip file has the original log file with application timestamps 
prefix, so I ran with --preprocess, which didn't fix the above lines and so are 
reported as unrecognized. I then worked around by reformatting those lines to 
confirm to the regular Full GC lines (in Vim, run this substitution: :%s/\(Full 
GC.*)\)\(\] \[Times:.* real=\)\(.*\) secs/\1], \300000 secs\2\3 secs/) .

The "GCTimeLimit" messages are a sure sign of bottlenecks (in fact, the JVM 
exited due to this in this case), so would not want to see these lines excluded.

OracleJDK 1.7 update 55

2014-07-08T13:23:02.860+0100: 22.706: [GC[YG occupancy: 129471 K (471872 
K)]2014-07-08T13:23:02.860+0100: 22.706: [Rescan (parallel) , 0.1468695 
secs]2014-07-08T13:23:03.017+0100: 22.853: [weak refs processing, 0.0001592 
secs]

Expand ParNewCmsConcurrentPreprocessAction to handle this logging:

1821.661: [GC 1821.661: [ParNew1821.661: [CMS-concurrent-sweep: 42.841/48.076 
secs] [Times: user=19.45 sys=0.45, real=48.06 secs]
: 36500K->3770K(38336K), 0.1767060 secs] 408349K->375618K(2092928K), 0.1769190 
secs] [Times: user=0.05 sys=0.00, real=0.18 secs]

ParNewCmsConcurrentEvent after preprocessing:
2210.281: [GC 2210.282: [ParNew2210.314: [CMS-concurrent-abortable-preclean: 
0.043/0.144 secs]: 212981K->3156K(242304K), 0.0364435 secs] 
4712182K->4502357K(4971420K), 0.0368807 secs] [Times: user=0.18 sys=0.02, 
real=0.04 secs]

Update  APPLICATION_STOPPED_TIME preprocessing for this logging, where the 
CONCURRENT event is on the 2nd line:

234784.781: [CMS-concurrent-abortable-preclean: 0.038/0.118 secs]Total time for 
which application threads were stopped: 0.0123330 seconds
 [Times: user=0.10 sys=0.00, real=0.12 secs]

Preprocessed:
Total time for which application threads were stopped: 0.0123330 seconds
234784.781: [CMS-concurrent-abortable-preclean: 0.038/0.118 secs] [Times: 
user=0.10 sys=0.00, real=0.12 secs]

I Use the G1 Garbage Collector from the SUN JDK 1.6
With this options

-XX:+UnlockExperimentalVMOptions -XX:+UseG1GC -XX:+PrintGC -XX:+PrintGCDetails 
-XX:+PrintGCTimeStamps

And garbagecat-1.0.0.jar report :
ERROR: No GC events found

Currently the match() methods in the event classes use String.matches(String), 
which causes it to compile the regex every time. Most of those classes already 
have a compiled regex (for data extraction), so they should use it.

Attached is a patch to implement this, which improves performance by around 
30-40% in my quick testing of a few GC logs.

Code convention: Use spaces, not tabs. 4 space indentation.

The following logging is currently grouped with concurrent mode failure for 
preprocessing and reporting:

382577.411: [Full GC 382577.412: [CMS382577.443: 
[CMS-concurrent-abortable-preclean: 0.045/1.321 secs] [Times: user=0.74 
sys=0.04, real=1.32 secs]
 (concurrent mode interrupted): 220423K->229092K(1810432K), 0.9884300 secs] 277129K->229092K(2007040K), [CMS Perm : 108039K->

However, it is different than a concurrent mode failure in that it is the 
result of a user requested action (e.g. a call to System.gc() or kill -3 in 
combination with -XX:+PrintClassHistogram causing a full GC before the 
histogram is output.

Break the "interrupted" out from the "failure" events, as analysis and action 
will be different for each.

I would really like to use this tool or a tool like it to analyze G1 collector 
data.

There seems to be some G1 code in here, but its not clear what level of G1 
support works.

Info around this would be useful.

Thanks,

Scott

Update  APPLICATION_CONCURRENT_TIME preprocessing to handle the following 
logging, where the CMS_CONCURRENT event is on the 2nd line:

408365.532: [CMS-concurrent-mark: 0.476/10.257 secs]Application time: 0.0576080 
seconds
 [Times: user=6.00 sys=0.28, real=10.26 secs]

Preprocessed:
Application time: 0.0576080 seconds
408365.532: [CMS-concurrent-mark: 0.476/10.257 secs] [Times: user=6.00 
sys=0.28, real=10.26 secs]

Handle additional concurrent mode failure patterns. For example:

1) Additional pattern Without "concurrent mode failure":
198.712: [Full GC 198.712: [CMS198.733: [CMS-concurrent-reset: 0.061/1.405 
secs]: 14037K->31492K(1835008K), 0.7953140 secs] 210074K->31492K(2096960K), 
[CMS Perm : 27817K->27784K(131072K)], 0.7955670 secs]

2) Preclean incremental mode:
5075.405: [GC 5075.405: [ParNew: 261760K->261760K(261952K), 0.0000750 
secs]5075.405: [CMS5081.144: [CMS-concurrent-preclean: 14.653/31.189 secs] 
(concurrent mode failure): 1796901K->1078231K(1835008K), 96.6130290 secs] 
2058661K->1078231K(2096960K) icms_dc=100 , 96.6140400 secs]

3) Sweep incrementatal mode:
"5062.472: [GC 5062.472: [ParNew: 261760K->261760K(261952K), 0.0000610 
secs]5062.473: [CMS5073.876: [CMS-concurrent-sweep: 11.563/14.268 secs] 
(concurrent mode failure): 1808263K->1078640K(1835008K), 88.9224480 secs] 
2070023K->1078640K(2096960K) icms_dc=100 , 88.9234900 secs]

4) Preprocessing with "Java HotSpot(TM) Server VM warning: " preceeding 
"bailing out":

1901.217: [GC 1901.217: [ParNew: 261760K->261760K(261952K), 0.0000570 
secs]1901.217: [CMSJava HotSpot(TM) Server VM warning: bailing out to 
foreground collection

What steps will reproduce the problem?

 java -jar garbagecat-1.0.0.jar -p gc_err.log 

What is the expected output? What do you see instead?

Exception in thread "main" java.lang.NullPointerException
    at org.eclipselabs.garbagecat.service.GcaManager.preprocess(GcaManager.java:101)

fix:
problem is caused by string initialized to null

in the body of GcaManager.preprocess():

instead:

String currentLogLine = null ;
String priorLogLine = null ;
String preprocessedLogLine = null ;

should be:

String currentLogLine = "" ;
String priorLogLine = "" ;
String preprocessedLogLine = "" ;

---------
by the way I made some code cleanings in this method
proposed version in attachment

cleanings:
1.
close only external streams, when you build one stream on another it is enough 
to close only external one

2. simplified while()