I have been working a lot recently with a bunch of test jobs that are intermittently getting stuck. Now it is possible to work out the point where the problem is occurring by looking at the date labels on the LOG output; but it is hard visually to pick these discontinuities out.
In order improve the output in a way that my brain can really quickly parse and identify I thought I would try my hand a bit of simple ASCII animation. I wrote a simple fixture that writes out a line every 1 minute while the test is running, here is a very simple implementation - I am sure there are better ways to do the animation!
import java.util.Timer;
import java.util.TimerTask;
import java.util.concurrent.TimeUnit;
public class TickTockFixture
{
private Timer timer;
@Before
public void setUp()
{
// Clean out any old timers
tearDown();
// Start a new timer
timer = new Timer();
timer.scheduleAtFixedRate(new TimerTask()
{
int counter = 0;
@Override
public void run()
{
StringBuilder sb = new StringBuilder(". TickTock : ");
int animation = counter++ % 10;
boolean direction = animation < 5;
int count = direction ? animation : 9 - animation;
sb.append(" ", 0, count);
sb.append(direction ? "/" : "\\");
sb.append(" ",0, 5-count);
sb.append(counter);
sb.append(" min(s)");
System.err.println(sb);
}
}, 0, TimeUnit.MINUTES.toMillis(1));
}
@After
public void tearDown()
{
if (timer!=null)
{
timer.cancel();
timer = null;
}
}
}
So does this help, well take a look at the - made up example - output below and try to spot the section of the log output where everything slows down. It is a lot easier with the ticking output which I think sticks out better because of the animation.
22-Feb-2013 11:54:30 Items in drs, going to tidy up
22-Feb-2013 11:54:40 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/Project1WebApp.war/WEB-INF/weblogic.xml
22-Feb-2013 11:54:40 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/Project1WebApp.war/WEB-INF/web.xml
22-Feb-2013 11:54:40 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/Project1WebApp.war/WEB-INF/classes/project1/Hello.class
22-Feb-2013 11:54:40 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/Project1WebApp.war/WEB-INF/classes/project1/
22-Feb-2013 11:54:40 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/Project1WebApp.war/WEB-INF/classes/
22-Feb-2013 11:54:40 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/Project1WebApp.war/WEB-INF/
22-Feb-2013 11:54:40 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/Project1WebApp.war/
22-Feb-2013 11:54:40 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/.module_marker
22-Feb-2013 11:54:40 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/META-INF/weblogic-application.xml
22-Feb-2013 11:54:40 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/META-INF/application.xml
22-Feb-2013 11:54:40 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/META-INF/
22-Feb-2013 11:54:40 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/.adrs-module.properties
22-Feb-2013 11:54:40 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/
22-Feb-2013 11:54:53 oracle.jdevimpl.webservices.tcpmonitor.config.AnalyzerInstance stop
WARNING: AnalyzerInstance aborting a stop as already appears to be stopped
22-Feb-2013 11:54:53 weblogic.logging.ServerLoggingHandler publish
WARNING: Container weblogic.wsee.jaxws.WLSContainer$BasicContainer@1232e17 doesn't support class com.sun.xml.ws.api.server.Module
22-Feb-2013 11:54:53 weblogic.logging.ServerLoggingHandler publish
WARNING: Container weblogic.wsee.jaxws.WLSContainer$BasicContainer@1232e17 doesn't support class com.sun.xml.ws.api.server.Module
trigger seeding of SecureRandom
. TickTock : \ 9 min(s)
. TickTock : \ 10 min(s)
. TickTock : / 11 min(s)
. TickTock : / 12 min(s)
. TickTock : / 13 min(s)
22-Feb-2013 11:59:50 done seeding SecureRandom
22-Feb-2013 11:59:53 weblogic.logging.ServerLoggingHandler publish
WARNING: Container weblogic.wsee.jaxws.WLSContainer$BasicContainer@1232e17 doesn't support class com.sun.xml.ws.api.server.Module
22-Feb-2013 12:00:01 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/Project1WebApp.war/WEB-INF/classes/project1/Hello.class
22-Feb-2013 12:00:01 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/Project1WebApp.war/WEB-INF/classes/project1/
22-Feb-2013 12:00:01 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/Project1WebApp.war/WEB-INF/classes/
22-Feb-2013 12:00:01 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/Project1WebApp.war/WEB-INF/
22-Feb-2013 12:00:01 Removing file:/scratch/gdavison/view_storage/gdavison_lt/oracle/jdeveloper/system12.1.2.0.40.65.92/o.j2ee/drs/Application1/Project1WebApp.war/