Skip to content

Commit

Permalink
Rely on System.currentTimeMillis only (not nanoTime) due to JENKINS-1…
Browse files Browse the repository at this point in the history 
…9778

On most Jenkins servers, System.nanoTime gives a more accurate reading of
elapsed time, because it is unaffected when the clock is changed. However,
on the Jenkins server in issue 19778, System.nanoTime jumps forwards
several times during the build, by about 30-40 seconds each time. Once the
build has finished, the Timestamper plugin reports an elapsed time of about
twice what it should be.

It does not seem possible for the plugin to reliably determine whether it
can use System.nanoTime, especially when running within a virtual machine.

Overall, it is not worthwhile for the plugin to rely on System.nanoTime.
  • Loading branch information
@StevenGBrown
StevenGBrown committed Nov 10, 2013
1 parent dc50c3a commit 4ec6bac
Show file tree
Hide file tree
Showing 12 changed files with 436 additions and 290 deletions.
13 changes: 0 additions & 13 deletions src/main/java/hudson/plugins/timestamper/Timestamp.java
View file
Expand Up @@ -37,24 +37,11 @@ public final class Timestamp {

/**
* The elapsed time in milliseconds since the start of the build.
* <p>
* Provided by <a href=
* "http://docs.oracle.com/javase/6/docs/api/java/lang/System.html#nanoTime()"
* >System.nanoTime()</a>.
* <p>
* For builds created with the Timestamper plugin prior to version 1.4, the
* elapsed time will instead be calculated based on {@link #millisSinceEpoch}
* and the start time of the build. In this case, the elapsed time values may
* not always be increasing and may be negative.
*/
public final long elapsedMillis;

/**
* The clock time in milliseconds since midnight, January 1, 1970 UTC.
* <p>
* Provided by <a href=
* "http://docs.oracle.com/javase/6/docs/api/java/lang/System.html#currentTimeMillis()"
* >System.currentTimeMillis()</a>.
*/
public final long millisSinceEpoch;

Expand Down
3 changes: 1 addition & 2 deletions src/main/java/hudson/plugins/timestamper/TimestamperOutputStream.java
View file
Expand Up @@ -115,9 +115,8 @@ private void writeTimestamps(byte[] b, int off, int len) throws IOException {
}

if (lineStartCount > 0) {
long nanoTime = System.nanoTime();
long currentTimeMillis = System.currentTimeMillis();
timestampsWriter.write(nanoTime, currentTimeMillis, lineStartCount);
timestampsWriter.write(currentTimeMillis, lineStartCount);
}
}

Expand Down
2 changes: 1 addition & 1 deletion src/main/java/hudson/plugins/timestamper/io/DumpTimestamps.java
View file
Expand Up @@ -57,7 +57,7 @@ public static void main(String... args) throws IOException {
File timestamperDir = new File(Joiner.on(' ').join(args));
System.out.println("timestamps");
dump(TimestampsWriterImpl.timestampsFile(timestamperDir), 1, System.out);
File timeShiftsFile = TimestampsWriterImpl.timeShiftsFile(timestamperDir);
File timeShiftsFile = TimestampsReader.timeShiftsFile(timestamperDir);
if (timeShiftsFile.isFile()) {
System.out.println("timeshifts");
dump(timeShiftsFile, 2, System.out);
Expand Down
10 changes: 7 additions & 3 deletions src/main/java/hudson/plugins/timestamper/io/TimestampsReader.java
View file
Expand Up @@ -51,6 +51,10 @@ public final class TimestampsReader implements Serializable {

private static final long serialVersionUID = 1L;

static File timeShiftsFile(File timestamperDir) {
return new File(timestamperDir, "timeshifts");
}

private final File timestampsFile;

private long filePointer;
Expand Down Expand Up @@ -87,7 +91,7 @@ public final class TimestampsReader implements Serializable {
public TimestampsReader(Run<?, ?> build) {
File timestamperDir = TimestampsWriterImpl.timestamperDir(build);
this.timestampsFile = TimestampsWriterImpl.timestampsFile(timestamperDir);
this.timeShiftsFile = TimestampsWriterImpl.timeShiftsFile(timestamperDir);
this.timeShiftsFile = timeShiftsFile(timestamperDir);
this.millisSinceEpoch = build.getTimeInMillis();
}

Expand Down Expand Up @@ -134,7 +138,7 @@ public Timestamp next() throws IOException {
* Read the next time-stamp by using an existing {@link RandomAccessFile}.
*/
private Timestamp next(final RandomAccessFile raf) throws IOException {
if (raf == null) {
if (raf == null || filePointer >= timestampsFile.length()) {
return null;
}
Varint.ByteReader byteReader = new Varint.ByteReader() {
Expand Down Expand Up @@ -162,7 +166,7 @@ public byte readByte() throws IOException {
}

private RandomAccessFile openTimestampsFile() throws FileNotFoundException {
if (!timestampsFile.isFile() || filePointer >= timestampsFile.length()) {
if (!timestampsFile.isFile()) {
return null;
}
return new RandomAccessFile(timestampsFile, "r");
Expand Down
5 changes: 1 addition & 4 deletions src/main/java/hudson/plugins/timestamper/io/TimestampsWriter.java
View file
Expand Up @@ -36,14 +36,11 @@ public interface TimestampsWriter extends Closeable {
/**
* Write a time-stamp for a line of the console log.
*
* @param nanoTime
* {@link System#nanoTime()}
* @param currentTimeMillis
* {@link System#currentTimeMillis()}
* @param times
* the number of times to write the time-stamp
* @throws IOException
*/
public void write(long nanoTime, long currentTimeMillis, int times)
throws IOException;
public void write(long currentTimeMillis, int times) throws IOException;
}
63 changes: 9 additions & 54 deletions src/main/java/hudson/plugins/timestamper/io/TimestampsWriterImpl.java
View file
Expand Up @@ -29,9 +29,6 @@
import java.io.FileOutputStream;
import java.io.IOException;
import java.util.Arrays;
import java.util.concurrent.TimeUnit;
import java.util.logging.Level;
import java.util.logging.Logger;

import com.google.common.io.Closeables;
import com.google.common.io.Files;
Expand All @@ -43,9 +40,6 @@
*/
public final class TimestampsWriterImpl implements TimestampsWriter {

private static final Logger LOGGER = Logger
.getLogger(TimestampsWriterImpl.class.getName());

private static final int BUFFER_SIZE = 1024;

static File timestamperDir(Run<?, ?> build) {
Expand All @@ -56,28 +50,16 @@ static File timestampsFile(File timestamperDir) {
return new File(timestamperDir, "timestamps");
}

static File timeShiftsFile(File timestamperDir) {
return new File(timestamperDir, "timeshifts");
}

private final File timestampsFile;

private FileOutputStream timestampsOutput;

private final File timeShiftsFile;

private FileOutputStream timeShiftsOutput;

private long entry;

/**
* Buffer that is used to store Varints prior to writing to a file.
*/
private final byte[] buffer = new byte[BUFFER_SIZE];

private long startNanos;

private long previousElapsedMillis;
private long buildStartTime;

private long previousCurrentTimeMillis;

Expand All @@ -90,8 +72,8 @@ static File timeShiftsFile(File timestamperDir) {
public TimestampsWriterImpl(Run<?, ?> build) throws IOException {
File timestamperDir = timestamperDir(build);
this.timestampsFile = timestampsFile(timestamperDir);
this.timeShiftsFile = timeShiftsFile(timestamperDir);
this.previousCurrentTimeMillis = build.getTimeInMillis();
this.buildStartTime = build.getTimeInMillis();
this.previousCurrentTimeMillis = buildStartTime;

Files.createParentDirs(timestampsFile);
boolean fileCreated = timestampsFile.createNewFile();
Expand All @@ -104,42 +86,21 @@ public TimestampsWriterImpl(Run<?, ?> build) throws IOException {
* {@inheritDoc}
*/
@Override
public void write(long nanoTime, long currentTimeMillis, int times)
throws IOException {
public void write(long currentTimeMillis, int times) throws IOException {
if (times < 1) {
return;
}
long elapsedMillis = currentTimeMillis - previousCurrentTimeMillis;
previousCurrentTimeMillis = currentTimeMillis;

// Write to time-stamps file.
if (entry == 0) {
startNanos = nanoTime;
}
// Write to the time-stamps file.
if (timestampsOutput == null) {
timestampsOutput = new FileOutputStream(timestampsFile);
}
long elapsedMillis = TimeUnit.NANOSECONDS.toMillis(nanoTime - startNanos);
long elapsedMillisDiff = elapsedMillis - previousElapsedMillis;
writeVarintsTo(timestampsOutput, elapsedMillisDiff);
writeVarintsTo(timestampsOutput, elapsedMillis);
if (times > 1) {
writeZerosTo(timestampsOutput, times - 1);
}
previousElapsedMillis = elapsedMillis;

// Write to time shifts file.
long expectedTimeMillis = previousCurrentTimeMillis + elapsedMillisDiff;
long timeMillisDiff = currentTimeMillis - expectedTimeMillis;
if (Math.abs(timeMillisDiff) > 1000) {
LOGGER.log(Level.FINE, "Time shift: " + timeMillisDiff);
if (timeShiftsOutput == null) {
timeShiftsOutput = new FileOutputStream(timeShiftsFile);
}
writeVarintsTo(timeShiftsOutput, entry, currentTimeMillis);
previousCurrentTimeMillis = currentTimeMillis;
} else {
previousCurrentTimeMillis = expectedTimeMillis;
}

entry += times;
}

/**
Expand Down Expand Up @@ -181,12 +142,6 @@ private void writeZerosTo(FileOutputStream outputStream, int n)
*/
@Override
public void close() throws IOException {
boolean threw = true;
try {
Closeables.close(timestampsOutput, false);
threw = false;
} finally {
Closeables.close(timeShiftsOutput, threw);
}
Closeables.close(timestampsOutput, false);
}
}
14 changes: 7 additions & 7 deletions src/test/java/hudson/plugins/timestamper/TimestamperOutputStreamTest.java
View file
Expand Up @@ -102,7 +102,7 @@ public void testPassThrough() throws Exception {
@Test
public void testWriteIntOneCharacter() throws Exception {
timestamperOutputStream.write('a');
verify(writer).write(anyLong(), anyLong(), eq(1));
verify(writer).write(anyLong(), eq(1));
}

/**
Expand All @@ -112,7 +112,7 @@ public void testWriteIntOneCharacter() throws Exception {
public void testWriteIntOneLine() throws Exception {
timestamperOutputStream.write('a');
timestamperOutputStream.write(NEWLINE);
verify(writer).write(anyLong(), anyLong(), eq(1));
verify(writer).write(anyLong(), eq(1));
}

/**
Expand All @@ -123,7 +123,7 @@ public void testWriteIntTwoLines() throws Exception {
timestamperOutputStream.write('a');
timestamperOutputStream.write(NEWLINE);
timestamperOutputStream.write('b');
verify(writer, times(2)).write(anyLong(), anyLong(), eq(1));
verify(writer, times(2)).write(anyLong(), eq(1));
}

/**
Expand All @@ -132,7 +132,7 @@ public void testWriteIntTwoLines() throws Exception {
@Test
public void testWriteByteArray() throws Exception {
timestamperOutputStream.write(data);
verify(writer).write(anyLong(), anyLong(), eq(1));
verify(writer).write(anyLong(), eq(1));
}

/**
Expand All @@ -141,7 +141,7 @@ public void testWriteByteArray() throws Exception {
@Test
public void testWriteByteArrayTwoLines() throws Exception {
timestamperOutputStream.write(dataTwoLines);
verify(writer).write(anyLong(), anyLong(), eq(2));
verify(writer).write(anyLong(), eq(2));
}

/**
Expand All @@ -150,7 +150,7 @@ public void testWriteByteArrayTwoLines() throws Exception {
@Test
public void testWriteByteArraySegment() throws Exception {
timestamperOutputStream.write(dataTwoLines, 0, data.length);
verify(writer).write(anyLong(), anyLong(), eq(1));
verify(writer).write(anyLong(), eq(1));
}

/**
Expand All @@ -159,6 +159,6 @@ public void testWriteByteArraySegment() throws Exception {
@Test
public void testWriteByteArraySegmentTwoLines() throws Exception {
timestamperOutputStream.write(dataTwoLines, 0, dataTwoLines.length);
verify(writer).write(anyLong(), anyLong(), eq(2));
verify(writer).write(anyLong(), eq(2));
}
}
4 changes: 1 addition & 3 deletions src/test/java/hudson/plugins/timestamper/action/TimestampsActionTest.java
View file
Expand Up @@ -43,7 +43,6 @@
import java.io.PrintWriter;
import java.util.Arrays;
import java.util.List;
import java.util.concurrent.TimeUnit;

import jenkins.model.Jenkins;

Expand Down Expand Up @@ -331,8 +330,7 @@ public void writeTimestamps() throws Exception {
TimestampsWriter writer = new TimestampsWriterImpl(build);
try {
for (long millisSinceEpoch : millisSinceEpochToWrite) {
writer.write(TimeUnit.MILLISECONDS.toNanos(millisSinceEpoch),
millisSinceEpoch, 1);
writer.write(millisSinceEpoch, 1);
}
} finally {
writer.close();
Expand Down
3 changes: 1 addition & 2 deletions src/test/java/hudson/plugins/timestamper/annotator/TimestampAnnotatorTest.java
View file
Expand Up @@ -41,7 +41,6 @@
import java.util.Collection;
import java.util.Collections;
import java.util.List;
import java.util.concurrent.TimeUnit;

import org.apache.commons.lang.SerializationUtils;
import org.junit.Before;
Expand Down Expand Up @@ -149,7 +148,7 @@ private List<Timestamp> writeTimestamps(int count) throws Exception {
try {
writer = new TimestampsWriterImpl(build);
for (int i = 0; i < count; i++) {
writer.write(TimeUnit.MILLISECONDS.toNanos(i), i, 1);
writer.write(i, 1);
timestamps.add(new Timestamp(i, i));
}
threw = false;
Expand Down

0 comments on commit 4ec6bac

Please sign in to comment.