Merge pull request #33 from takashi-ishio/issue31

Fix #31

DataFormat.md

@@ -245,16 +245,15 @@ The event name is defined in the class `selogger.EventType`.
 |Object manipulation (OBJECT)|OBJECT_CONSTANT_LOAD|When a constant object (usually String) is loaded by the instruction.|Object loaded by the instruction.  This may be null.|
 |                            |OBJECT_INSTANCEOF|Before the INSTANCEOF instruction is executed.|Object whose class is checked by the instruction|
 |                            |OBJECT_INSTANCEOF_RESULT|After the INSTANCEOF instruction is executed.|Result (true or false) of the instruction|
-|Local variables (LOCAL)|LOCAL_LOAD|Before the value of the local variable is read by a local variable instruction (one of ALOD, DLOAD, FLOAD, ILOAD, and LLOAD)|Value read from the variable|
-|                       |LOCAL_STORE|Before the value is written to the local variable by an instruction (one of ASTORE, DSTORE, FSTORE, ISTORE, and LSTORE) |Value written to the variable|
-|                       |LOCAL_INCREMENT|After the local variable is updated by an IINC instruction.  An IINC instruction is not only for `i++`; it is also used for `i+=k` and `i-=k` if `k` is constant (depending on a compiler).|Value written to the variable by an increment instruction|
-|                       |RET|This event corresponds to a RET instruction for subroutine call.  The current version does not generate this event.||
-|Control-flow events (LABEL)|LABEL|This event is recorded when an execution passed a particular code location. LABEL itself is not a Java bytecode, a pseudo instruction inserted by ASM bytecode manipulation library used by SELogger.|A dataId corresponding to the previous program location is recorded so that a user can trace a control-flow path.|
-|                           |CATCH_LABEL|This event is recorded when an execution entered a catch/finally block.|A dataId corresponding to the previous program location (that is likely where an exception was thrown) is recorded.|
-|                           |CATCH|When an execution entered a catch/finally block, immediately after a CATCH_LABEL event, before any instructions in the catch/finally block is executed.|Exception object caught by the block|
-|                           |JUMP|This event represents a jump instruction in bytecode. |The event itself is not directly recorded in a trace.  The dataId of this event may appear in LABEL events.|
-|                           |DIVIDE|This event represents an arithmetic division instruction (IDIV).|The event itself is not directly recorded in a trace.  The dataId of this event may appear in LABEL events.|
-|                           |LINE_NUMBER|This event represents an execution of a line of source code.  As a single line of code may be compiled into separated bytecode blocks, a number of LINE_NUMBER events having different data ID may point to the same line number.||
+|Local variables (LOCAL)     |LOCAL_LOAD|Before the value of the local variable is read by a local variable instruction (one of ALOD, DLOAD, FLOAD, ILOAD, and LLOAD)|Value read from the variable|
+|                            |LOCAL_STORE|Before the value is written to the local variable by an instruction (one of ASTORE, DSTORE, FSTORE, ISTORE, and LSTORE) |Value written to the variable|
+|                            |LOCAL_INCREMENT|After the local variable is updated by an IINC instruction.  An IINC instruction is not only for `i++`; it is also used for `i+=k` and `i-=k` if `k` is constant (depending on a compiler).|Value written to the variable by an increment instruction|
+|                            |RET|This event corresponds to a RET instruction for subroutine call.  The current version does not generate this event.||
+|Control-flow events (LABEL) |LABEL|This event is recorded when an execution passed a particular code location. LABEL itself is not a Java bytecode, a pseudo instruction inserted by ASM bytecode manipulation library used by SELogger.|A bytecode instruction index of the previous program location is recorded so that a user can trace a control-flow path.|
+|                            |CATCH_LABEL|This event is recorded when an execution entered a catch/finally block.|A bytecode instruction index of the previous program location (that is likely where an exception was thrown) is recorded.|
+|                            |JUMP|This event represents a jump instruction in bytecode.  |While this event appears in a list of IDs to show the instruction index, the event itself is not directly recorded in a trace.|
+|Line number events (LINE)   |LINE_NUMBER|This event represents an execution of a line of source code.  As a single line of code may be compiled into separated bytecode blocks, a number of LINE_NUMBER events having different data ID may point to the same line number.||
+|Other events                |CATCH|This event is recorded when an execution entered a catch/finally block.  This event is observed if any of CALL, FIELD, ARRAY, and SYNC events are observed.|Exception object caught by the block|
 
 
 

src/selogger/weaver/WeaveConfig.java

@@ -186,7 +186,6 @@ public boolean recordCatch() {
 		return recordMethodCall() || 
 				recordFieldAccess() || 
 				recordArrayInstructions() ||
-				recordLabel() ||
 				recordSynchronization();
 	}
 

src/selogger/weaver/method/MethodTransformer.java

@@ -338,18 +338,18 @@ public void visitCode() {
 		if (config.recordExecution() || config.recordCatch()) {
 			super.visitTryCatchBlock(startLabel, endLabel, endLabel, "java/lang/Throwable");
 
-			// Create an integer to record a jump/exception 
-			if (config.recordCatch()) {
-				lastLocationVar = newLocal(Type.INT_TYPE);
-				generateLocationUpdate();
-			}
-
 			if (!methodName.equals("<init>")) { // In a constructor, a try block cannot start before a super() call.
 				super.visitLabel(startLabel);
 				isStartLabelLocated = true;
 			}
 		}
-
+
+		// Create an integer to record a jump/exception 
+		if (config.recordLabel()) {
+			lastLocationVar = newLocal(Type.INT_TYPE);
+			generateLocationUpdate();
+		}
+
 		if (config.recordExecution()) {
 
 			// Generate instructions to record parameters
@@ -420,20 +420,21 @@ public void visitLabel(Label label) {
 		if (l != null) {
 			currentLine = l.intValue();
 		}
-
-		if (config.recordCatch() && catchBlockInfo.containsKey(label)) {
-			// If the label is a catch block, record the previous location and an exception.
-			generateNewVarInsn(Opcodes.ILOAD, lastLocationVar);
-			generateLogging(EventType.CATCH_LABEL, Descriptor.Integer, null);
-			generateLoggingPreservingStackTop(EventType.CATCH, Descriptor.Object, catchBlockInfo.get(label));
-			generateLocationUpdate();
-		} else if (config.recordLabel()) {
+
+		boolean isCatchBlockHead = catchBlockInfo.containsKey(label);
+		if (config.recordLabel()) {
 			// For a regular label, record a previous location.
 			generateNewVarInsn(Opcodes.ILOAD, lastLocationVar);
-			generateLogging(EventType.LABEL, Descriptor.Integer, null);
+			EventType eventType = isCatchBlockHead ? EventType.CATCH_LABEL: EventType.LABEL;
+			generateLogging(eventType, Descriptor.Integer, null);
 			generateLocationUpdate();
 		}
 
+		if (config.recordCatch() && isCatchBlockHead) {
+			// If the label is a catch block, record the exception.
+			generateLoggingPreservingStackTop(EventType.CATCH, Descriptor.Object, catchBlockInfo.get(label));
+		}
+
 		instructionIndex++;
 	}
 
@@ -481,11 +482,12 @@ public void visitMaxs(int maxStack, int maxLocals) {
 			//     throw t; 
 			//   }
 
-			// Assume an exception object on the stack
+			// Generate a label representing the end of a try-catch block for the method body.
+			// This label is not followed by recordLabel because this is an artificial label
 			super.visitLabel(endLabel);
+
+			// Generate logging code assuming an exception object on the stack
 			if (config.recordCatch()) {
-				generateNewVarInsn(Opcodes.ILOAD, lastLocationVar);
-				generateLogging(EventType.CATCH_LABEL, Descriptor.Integer, InstructionAttributes.of(ATTRIBUTE_LOCATION, "exceptional-exit"));
 				InstructionAttributes attr = InstructionAttributes.of(ATTRIBUTE_LOCATION, "exceptional-exit")
 						.and(ATTRIBUTE_TYPE, "Ljava/lang/Throwable;")
 						.and(ATTRIBUTE_BLOCK_START, 0)
@@ -589,6 +591,9 @@ public void visitMethodInsn(int opcode, String owner, String name, String desc,
 			assert newInstruction.getTypeName().equals(owner);
 		}
 
+		// Store the current location for exceptional exit
+		if (config.recordLabel()) generateLocationUpdate();
+
 		// Generate instructions to record method call and its parameters
 		if (config.recordMethodCall()) {
 
@@ -652,8 +657,6 @@ public void visitMethodInsn(int opcode, String owner, String name, String desc,
 					generateNewVarInsn(params.getLoadInstruction(i), params.getLocalVar(i));
 				}
 
-				// Store the current location for exceptional exit
-				generateLocationUpdate();
 				// Call the original method
 				super.visitMethodInsn(opcode, owner, name, desc, itf);
 
@@ -681,9 +684,6 @@ public void visitMethodInsn(int opcode, String owner, String name, String desc,
 				} 
 				generateLogging(EventType.CALL, Descriptor.Void, attr);
 
-				// Store the current location for exceptional exit
-				generateLocationUpdate();
-
 				// Call the original method
 				super.visitMethodInsn(opcode, owner, name, desc, itf);
 
@@ -734,9 +734,11 @@ public void visitMethodInsn(int opcode, String owner, String name, String desc,
 	 * to a local variable to track the control flow.  
 	 */
 	private void generateLocationUpdate() {
-		assert lastLocationVar >= 0: "Uninitialized lastLocationVar";
-		super.visitLdcInsn(instructionIndex);
-		generateNewVarInsn(Opcodes.ISTORE, lastLocationVar);
+		if (config.recordLabel()) {
+			assert lastLocationVar >= 0: "Uninitialized lastLocationVar";
+			super.visitLdcInsn(instructionIndex);
+			generateNewVarInsn(Opcodes.ISTORE, lastLocationVar);
+		}
 	}
 
 	/**
@@ -813,31 +815,27 @@ public void visitInsn(int opcode) {
 			}
 			super.visitInsn(opcode);
 		} else if (opcode == Opcodes.ATHROW) {
+			if (config.recordLabel()) generateLocationUpdate();
 			if (config.recordExecution()) {
 				generateLoggingPreservingStackTop(EventType.METHOD_THROW, Descriptor.Object, null);
-				if (config.recordCatch()) {
-					generateLocationUpdate();
-				}
-			} else if (config.recordCatch()) {
-				// Assign a thread ID just for location
-				nextDataId(EventType.METHOD_THROW, Descriptor.Void, null);
-				generateLocationUpdate();
 			}
-
 			super.visitInsn(opcode);
 		} else if (OpcodesUtil.isArrayLoad(opcode)) {
+			if (config.recordLabel()) generateLocationUpdate();
 			if (config.recordArrayInstructions()) {
 				generateRecordArrayLoad(opcode);
 			} else {
 				super.visitInsn(opcode);
 			}
 		} else if (OpcodesUtil.isArrayStore(opcode)) {
+			if (config.recordLabel()) generateLocationUpdate();
 			if (config.recordArrayInstructions() && !(config.ignoreArrayInitializer() && afterNewArray)) {
 				generateRecordArrayStore(opcode);
 			} else {
 				super.visitInsn(opcode);
 			}
 		} else if (opcode == Opcodes.ARRAYLENGTH) {
+			if (config.recordLabel()) generateLocationUpdate();
 			if (config.recordArrayInstructions()) {
 				generateLoggingPreservingStackTop(EventType.ARRAY_LENGTH, Descriptor.Object, null);
 				super.visitInsn(opcode); // -> [ arraylength ]
@@ -846,18 +844,19 @@ public void visitInsn(int opcode) {
 				super.visitInsn(opcode);
 			}
 		} else if (opcode == Opcodes.MONITORENTER) {
+			if (config.recordLabel()) generateLocationUpdate();
 			if (config.recordSynchronization()) {
 				super.visitInsn(Opcodes.DUP);
 				super.visitInsn(Opcodes.DUP);
 				// Monitor enter fails if the argument is null.
 				generateLogging(EventType.MONITOR_ENTER, Descriptor.Object, null);
-				generateLocationUpdate();
 				super.visitInsn(opcode); // Enter the monitor
 				generateLogging(EventType.MONITOR_ENTER_RESULT, Descriptor.Object, null);
 			} else {
 				super.visitInsn(opcode);
 			}
 		} else if (opcode == Opcodes.MONITOREXIT) {
+			if (config.recordLabel()) generateLocationUpdate();
 			if (config.recordSynchronization()) {
 				super.visitInsn(Opcodes.DUP); // -> [objectref, objectref]
 				generateLogging(EventType.MONITOR_EXIT, Descriptor.Object, null);
@@ -869,12 +868,8 @@ public void visitInsn(int opcode) {
 				opcode == Opcodes.FDIV ||
 				opcode == Opcodes.IDIV ||
 				opcode == Opcodes.LDIV) {
-			if (config.recordCatch()) {
-				generateLocationUpdate();
-				super.visitInsn(opcode);
-			} else {
-				super.visitInsn(opcode);
-			}
+			if (config.recordLabel()) generateLocationUpdate();
+			super.visitInsn(opcode);
 		} else {
 			super.visitInsn(opcode);
 		}
@@ -886,6 +881,8 @@ public void visitInsn(int opcode) {
 	 */
 	@Override
 	public void visitInvokeDynamicInsn(String name, String desc, Handle bsm, Object... bsmArgs) {
+		if (config.recordLabel()) generateLocationUpdate();
+
 		if (config.recordMethodCall()) {
 			// Duplicate an object reference to record the created object
 			InstructionAttributes attr = InstructionAttributes.of(ATTRIBUTE_NAME, name)
@@ -990,8 +987,6 @@ private void generateRecordArrayLoad(int opcode) {
 		super.visitLdcInsn(dataId); // [array, index, array, index, id]
 		super.visitMethodInsn(Opcodes.INVOKESTATIC, LOGGER_CLASS, "recordArrayLoad", "(Ljava/lang/Object;II)V", false);
 
-		generateLocationUpdate();
-
 		// the original instruction [array, index] -> [value]
 		super.visitInsn(opcode);
 
@@ -1027,7 +1022,6 @@ private void generateRecordArrayStore(int opcode) {
 
 		generateNewVarInsn(OpcodesUtil.getLoadInstruction(elementDesc), valueStoreVar); // -> [array, index, value]
 
-		generateLocationUpdate();
 		super.visitInsn(opcode); // original store instruction
 
 	}
@@ -1038,6 +1032,8 @@ private void generateRecordArrayStore(int opcode) {
 	 */
 	@Override
 	public void visitFieldInsn(int opcode, String owner, String name, String desc) {
+		if (config.recordLabel()) generateLocationUpdate();
+
 		if (!config.recordFieldAccess()) {
 			super.visitFieldInsn(opcode, owner, name, desc);
 			instructionIndex++;
@@ -1061,8 +1057,6 @@ public void visitFieldInsn(int opcode, String owner, String name, String desc) {
 		} else if (opcode == Opcodes.GETFIELD) {
 			generateLoggingPreservingStackTop(EventType.GET_INSTANCE_FIELD, Descriptor.Object, attr);
 
-			generateLocationUpdate();
-
 			// Execute GETFIELD
 			super.visitFieldInsn(opcode, owner, name, desc); // -> [value]
 
@@ -1082,8 +1076,6 @@ public void visitFieldInsn(int opcode, String owner, String name, String desc) {
 
 					// Record a value.
 					generateLoggingPreservingStackTop(EventType.PUT_INSTANCE_FIELD_VALUE, Descriptor.get(desc), attr);
-
-					generateLocationUpdate();
 
 					// Original Instruction
 					super.visitFieldInsn(opcode, owner, name, desc);
@@ -1094,7 +1086,6 @@ public void visitFieldInsn(int opcode, String owner, String name, String desc) {
 					generateLogging(EventType.PUT_INSTANCE_FIELD, Descriptor.Object, attr);
 					generateLogging(EventType.PUT_INSTANCE_FIELD_VALUE, Descriptor.get(desc), attr);
 
-					generateLocationUpdate();
 					super.visitFieldInsn(opcode, owner, name, desc);
 				}
 			} else {

tests/selogger/logging/io/LatestEventLoggerTest.java

@@ -17,6 +17,7 @@
 import selogger.EventType;
 import selogger.logging.io.LatestEventLogger.ObjectRecordingStrategy;
 import selogger.logging.util.ObjectId;
+import selogger.logging.util.ThreadId;
 import selogger.weaver.DataInfo;
 import selogger.weaver.MethodInfo;
 import selogger.weaver.method.Descriptor;
@@ -213,5 +214,27 @@ public void testObjectId() {
 		Assert.assertEquals("test", exceptionId.getContent());
 		Assert.assertEquals("java.lang.Throwable", exceptionId.getClassName());
 	}
-
+
+	@Test
+	public void testPrimitiveTypes() {
+		LatestEventLogger logger = new LatestEventLogger(null, 1, ObjectRecordingStrategy.Weak, true, null);
+		logger.recordEvent(0, (char)1);
+		logger.recordEvent(1, (short)2);
+		logger.recordEvent(2, Float.NaN);
+		logger.recordEvent(3, (byte)4);
+		logger.recordEvent(4, 5D);
+		logger.recordEvent(5, true);
+
+		LatestEventBuffer buf = logger.prepareBuffer(int.class, 1);
+		long seq = buf.getSeqNum(0);
+		Assert.assertEquals("1,1,2," + seq + "," + ThreadId.get(), buf.toString());
+
+		buf = logger.prepareBuffer(byte.class, 3);
+		seq = buf.getSeqNum(0);
+		Assert.assertEquals("1,1,4," + seq + "," + ThreadId.get(), buf.toString());
+
+		buf = logger.prepareBuffer(float.class, 2);
+		seq = buf.getSeqNum(0);
+		Assert.assertEquals("1,1,NaN," + seq + "," + ThreadId.get(), buf.toString());
+	}
 }

tests/selogger/testdata/SimpleTarget.java

@@ -180,5 +180,21 @@ public void testAll() {
 		useLocal();
 
 	}
+
+	public boolean nestedConditions(int x, int y) {
+		if ((x > 0 && y > 0) && (x==y)) {
+			return true;
+		} else {
+			return false;
+		}
+	}
+
+	public int divide(int x) {
+		try {
+			return 1 / x;
+		} catch (ArithmeticException e) {
+			return 0;
+		}
+	}
 
 }

tests/selogger/weaver/ClassInfoTest.java

@@ -0,0 +1,30 @@
+package selogger.weaver;
+
+import org.junit.Assert;
+import org.junit.Test;
+
+public class ClassInfoTest {
+
+	@Test
+	public void testClassInfo() {
+		ClassInfo c = new ClassInfo(1, "container", "filename", "classname", LogLevel.Normal, "0101", "#id");
+		String s = c.toString();
+		ClassInfo c2 = ClassInfo.parse(s);
+
+		Assert.assertEquals(1, c.getClassId());
+		Assert.assertEquals("#id", c.getClassLoaderIdentifier());
+		Assert.assertEquals("classname", c.getClassName());
+		Assert.assertEquals("filename", c.getFilename());
+		Assert.assertEquals("container", c.getContainer());
+		Assert.assertEquals(LogLevel.Normal, c.getLoglevel());
+		Assert.assertEquals("0101", c.getHash());
+
+		Assert.assertEquals(1, c2.getClassId());
+		Assert.assertEquals("#id", c2.getClassLoaderIdentifier());
+		Assert.assertEquals("classname", c2.getClassName());
+		Assert.assertEquals("filename", c2.getFilename());
+		Assert.assertEquals("container", c2.getContainer());
+		Assert.assertEquals(LogLevel.Normal, c2.getLoglevel());
+		Assert.assertEquals("0101", c2.getHash());
+	}
+}