Skip to content

Commit fd7bb09

Browse files
KarstenSchnitterKarstenSchnitter
authored
Refactor response time measurement in RequestRecord (#101)
* Refactor response time measurement in RequestRecord Removes the SimpleDateFormat in favour of java.time.Instant. This also removes the `synchronized` block required to protect SDF. Tests were improved as well. In total, this improves cpu usage during request handling. It is hard to give definite numbers on the improvement, since the synchronized statement could have lead to congestion. * Remove Warnings in logback & log4j2 RequestRecordTest
1 parent 2587546 commit fd7bb09

File tree

6 files changed

+69
-158
lines changed

6 files changed

+69
-158
lines changed

‎cf-java-logging-support-core/src/main/java/com/sap/hcp/cf/logging/common/DateTimeValue.java‎

Lines changed: 0 additions & 72 deletions
This file was deleted.

‎cf-java-logging-support-core/src/main/java/com/sap/hcp/cf/logging/common/request/RequestRecord.java‎

Lines changed: 22 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,8 @@
11
package com.sap.hcp.cf.logging.common.request;
22

3+
import java.time.Clock;
4+
import java.time.Duration;
5+
import java.time.Instant;
36
import java.util.HashMap;
47
import java.util.HashSet;
58
import java.util.Map;
@@ -11,7 +14,6 @@
1114
import com.fasterxml.jackson.jr.ob.JSON;
1215
import com.fasterxml.jackson.jr.ob.JSONComposer;
1316
import com.fasterxml.jackson.jr.ob.comp.ObjectComposer;
14-
import com.sap.hcp.cf.logging.common.DateTimeValue;
1517
import com.sap.hcp.cf.logging.common.Defaults;
1618
import com.sap.hcp.cf.logging.common.DoubleValue;
1719
import com.sap.hcp.cf.logging.common.Fields;
@@ -67,10 +69,8 @@ public enum Direction {
6769
IN, OUT
6870
}
6971

70-
private long startNano = 0;
71-
private long endNano = 0;
72-
private long startMs = 0;
73-
private long endMs = 0;
72+
private Instant start;
73+
private Instant end;
7474

7575
private Direction direction = Direction.IN;
7676

@@ -184,12 +184,8 @@ public void resetContext() {
184184
* @return the assigned start time.
185185
*/
186186
public long start() {
187-
startMs = System.currentTimeMillis();
188-
startNano = System.nanoTime();
189-
if (startNano > endNano) {
190-
endNano = startNano;
191-
}
192-
return startMs;
187+
start = Instant.now(ClockHolder.getInstance());
188+
return start.toEpochMilli();
193189
}
194190

195191
/**
@@ -198,10 +194,8 @@ public long start() {
198194
* @return the assigned end time.
199195
*/
200196
public long stop() {
201-
endMs = System.currentTimeMillis();
202-
endNano = System.nanoTime();
203-
204-
return endMs;
197+
end = Instant.now(ClockHolder.getInstance());
198+
return end.toEpochMilli();
205199
}
206200

207201
@Override
@@ -239,11 +233,11 @@ private void finish() {
239233
* sure, we stopped the timer and then compute the delta
240234
*/
241235
if (!fields.containsKey(Fields.RESPONSE_TIME_MS)) {
242-
if (endMs == 0) {
236+
if (end == null) {
243237
stop();
244238
}
245-
setEndTimingTag(new DateTimeValue(endMs).toString());
246-
addValue(Fields.RESPONSE_TIME_MS, new DoubleValue((endNano - startNano) / 1000000.0));
239+
setEndTimingTag(end.toString());
240+
addValue(Fields.RESPONSE_TIME_MS, new DoubleValue(Duration.between(start, end).toNanos() / 1_000_000.0));
247241
} else {
248242
Value respTime = fields.get(Fields.RESPONSE_TIME_MS);
249243
if (respTime != null) {
@@ -253,10 +247,10 @@ private void finish() {
253247
} else if (LongValue.class.isAssignableFrom(respTime.getClass())) {
254248
delta = ((Long) respTime.getValue()).longValue();
255249
}
256-
setEndTimingTag(new DateTimeValue(startMs + delta).toString());
250+
setEndTimingTag(start.plusMillis(delta).toString());
257251
}
258252
}
259-
setStartTimingTag(new DateTimeValue(startMs).toString());
253+
setStartTimingTag(start.toString());
260254
}
261255

262256
private void setStartTimingTag(String dateValue) {
@@ -280,4 +274,12 @@ private void setEndTimingTag(String dateValue) {
280274
addTag(tag, dateValue);
281275

282276
}
277+
278+
static class ClockHolder {
279+
static Clock instance = Clock.systemUTC();
280+
281+
public static Clock getInstance() {
282+
return ClockHolder.instance;
283+
}
284+
}
283285
}

‎cf-java-logging-support-core/src/test/java/com/sap/hcp/cf/logging/common/TestDateTimeValue.java‎

Lines changed: 0 additions & 29 deletions
This file was deleted.

cf-java-logging-support-core/src/test/java/com/sap/hcp/cf/logging/common/request/TestRequestRecord.java renamed to cf-java-logging-support-core/src/test/java/com/sap/hcp/cf/logging/common/request/RequestRecordTest.java

Lines changed: 39 additions & 26 deletions
Original file line numberDiff line numberDiff line change
@@ -1,14 +1,19 @@
11
package com.sap.hcp.cf.logging.common.request;
22

3-
import static org.hamcrest.Matchers.greaterThan;
4-
import static org.hamcrest.Matchers.lessThanOrEqualTo;
5-
import static org.hamcrest.core.Is.is;
3+
import static org.hamcrest.MatcherAssert.assertThat;
4+
import static org.hamcrest.Matchers.equalTo;
5+
import static org.hamcrest.Matchers.greaterThanOrEqualTo;
6+
import static org.hamcrest.Matchers.is;
67
import static org.hamcrest.core.IsNot.not;
78
import static org.hamcrest.core.IsNull.nullValue;
8-
import static org.junit.Assert.assertThat;
99

1010
import java.io.IOException;
11+
import java.time.Clock;
12+
import java.time.Duration;
13+
import java.time.Instant;
14+
import java.time.ZoneOffset;
1115

16+
import org.junit.Before;
1217
import org.junit.Test;
1318
import org.slf4j.MDC;
1419

@@ -17,13 +22,20 @@
1722
import com.sap.hcp.cf.logging.common.Defaults;
1823
import com.sap.hcp.cf.logging.common.DoubleValue;
1924
import com.sap.hcp.cf.logging.common.Fields;
20-
import com.sap.hcp.cf.logging.common.request.RequestRecord;
2125
import com.sap.hcp.cf.logging.common.request.RequestRecord.Direction;
2226

23-
public class TestRequestRecord {
27+
public class RequestRecordTest {
28+
29+
private static final Clock FIXED_CLOCK_EPOCH = Clock.fixed(Instant.EPOCH, ZoneOffset.UTC);
30+
private static final Duration RESPONSE_DELAY = Duration.ofMillis(150);
2431

2532
private RequestRecord rrec;
2633

34+
@Before
35+
public void resetRequestRecordClock() {
36+
setRequestRecordClock(FIXED_CLOCK_EPOCH);
37+
}
38+
2739
@Test
2840
public void testDefaults() throws JSONObjectException, IOException {
2941
String layer = "testDefaults";
@@ -34,7 +46,7 @@ public void testDefaults() throws JSONObjectException, IOException {
3446
assertThat(getField(Fields.REQUEST_SIZE_B), is("-1"));
3547
assertThat(getField(Fields.REQUEST_RECEIVED_AT), not(nullValue()));
3648
assertThat(getField(Fields.REQUEST_RECEIVED_AT), not(nullValue()));
37-
assertThat(Double.valueOf(getField(Fields.RESPONSE_TIME_MS)), greaterThan(new Double(0.0)));
49+
assertThat(Double.valueOf(getField(Fields.RESPONSE_TIME_MS)), greaterThanOrEqualTo(0.0d));
3850

3951
assertThat(getField(Fields.REQUEST), is(Defaults.UNKNOWN));
4052
assertThat(getField(Fields.REMOTE_IP), is(Defaults.UNKNOWN));
@@ -101,41 +113,42 @@ public void testResponseTimeIn() throws JSONObjectException, IOException {
101113
MDC.clear();
102114
String layer = "testResponseTimeIn";
103115
rrec = new RequestRecord(layer);
104-
long start = rrec.start();
105-
doWait(150);
106-
long end = rrec.stop();
116+
rrec.start();
117+
advanceRequestRecordClock(RESPONSE_DELAY);
118+
rrec.stop();
107119
assertThat(getField(Fields.LAYER), is(layer));
108120
assertThat(getField(Fields.DIRECTION), is(Direction.IN.toString()));
109-
assertThat(Double.valueOf(getField(Fields.RESPONSE_TIME_MS)).longValue(), lessThanOrEqualTo(Double.valueOf(end -
110-
start)
111-
.longValue()));
112-
assertThat(getField(Fields.RESPONSE_SENT_AT), not(nullValue()));
113-
assertThat(getField(Fields.REQUEST_RECEIVED_AT), not(nullValue()));
121+
assertThat(Double.valueOf(getField(Fields.RESPONSE_TIME_MS)), is(RESPONSE_DELAY.getNano() / 1_000_000.0));
122+
assertThat(getField(Fields.RESPONSE_SENT_AT), is(equalTo(Instant.EPOCH.plus(RESPONSE_DELAY).toString())));
123+
assertThat(getField(Fields.REQUEST_RECEIVED_AT), is(equalTo(Instant.EPOCH.toString())));
114124
}
115125

116126
@Test
117127
public void testResponseTimeOut() throws JSONObjectException, IOException {
118128
MDC.clear();
119129
String layer = "testResponseTimeOut";
120130
rrec = new RequestRecord(layer, Direction.OUT);
121-
long start = rrec.start();
122-
doWait(150);
123-
long end = rrec.stop();
131+
rrec.start();
132+
advanceRequestRecordClock(RESPONSE_DELAY);
133+
rrec.stop();
124134
assertThat(getField(Fields.LAYER), is(layer));
125135
assertThat(getField(Fields.DIRECTION), is(Direction.OUT.toString()));
126-
assertThat(Double.valueOf(getField(Fields.RESPONSE_TIME_MS)).longValue(), lessThanOrEqualTo(Double.valueOf(end -
127-
start)
128-
.longValue()));
136+
assertThat(Double.valueOf(getField(Fields.RESPONSE_TIME_MS)), is(RESPONSE_DELAY.getNano() / 1_000_000.0));
129137
assertThat(getField(Fields.RESPONSE_RECEIVED_AT), not(nullValue()));
130138
assertThat(getField(Fields.REQUEST_SENT_AT), not(nullValue()));
131139
}
132140

133-
private void doWait(long p) {
134-
try {
135-
Thread.sleep(p);
136-
} catch (Exception e) {
141+
private Clock getRequestRecordClock() {
142+
return RequestRecord.ClockHolder.getInstance();
143+
}
144+
145+
private void setRequestRecordClock(Clock clock) {
146+
RequestRecord.ClockHolder.instance = clock;
147+
}
137148

138-
}
149+
private void advanceRequestRecordClock(Duration duration) {
150+
Clock advancedClock = Clock.offset(getRequestRecordClock(), duration);
151+
setRequestRecordClock(advancedClock);
139152
}
140153

141154
private String getField(String fieldName) throws JSONObjectException, IOException {

cf-java-logging-support-log4j2/src/test/java/com/sap/hcp/cf/logging/common/request/TestRequestRecord.java renamed to cf-java-logging-support-log4j2/src/test/java/com/sap/hcp/cf/logging/common/request/RequestRecordTest.java

Lines changed: 4 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -1,12 +1,12 @@
11
package com.sap.hcp.cf.logging.common.request;
22

3+
import static org.hamcrest.MatcherAssert.assertThat;
34
import static org.hamcrest.Matchers.greaterThan;
45
import static org.hamcrest.Matchers.lessThanOrEqualTo;
56
import static org.hamcrest.core.Is.is;
67
import static org.hamcrest.core.IsNot.not;
78
import static org.hamcrest.core.IsNull.notNullValue;
89
import static org.hamcrest.core.IsNull.nullValue;
9-
import static org.junit.Assert.assertThat;
1010

1111
import java.io.IOException;
1212

@@ -21,12 +21,11 @@
2121
import com.sap.hcp.cf.logging.common.DoubleValue;
2222
import com.sap.hcp.cf.logging.common.Fields;
2323
import com.sap.hcp.cf.logging.common.Markers;
24-
import com.sap.hcp.cf.logging.common.request.RequestRecord;
2524
import com.sap.hcp.cf.logging.common.request.RequestRecord.Direction;
2625

27-
public class TestRequestRecord extends AbstractTest {
26+
public class RequestRecordTest extends AbstractTest {
2827

29-
private final Logger logger = LoggerFactory.getLogger(TestRequestRecord.class);
28+
private final Logger logger = LoggerFactory.getLogger(RequestRecordTest.class);
3029
private RequestRecord rrec;
3130

3231
@Test
@@ -41,7 +40,7 @@ public void testDefaults() throws JSONObjectException, IOException {
4140
assertThat(getField(Fields.REQUEST_SIZE_B), is("-1"));
4241
assertThat(getField(Fields.REQUEST_RECEIVED_AT), not(nullValue()));
4342
assertThat(getField(Fields.REQUEST_RECEIVED_AT), not(nullValue()));
44-
assertThat(Double.valueOf(getField(Fields.RESPONSE_TIME_MS)), greaterThan(new Double(0.0)));
43+
assertThat(Double.valueOf(getField(Fields.RESPONSE_TIME_MS)), greaterThan(0.0d));
4544

4645
assertThat(getField(Fields.REQUEST), is(Defaults.UNKNOWN));
4746
assertThat(getField(Fields.REMOTE_IP), is(Defaults.UNKNOWN));

cf-java-logging-support-logback/src/test/java/com/sap/hcp/cf/logging/common/request/TestRequestRecord.java renamed to cf-java-logging-support-logback/src/test/java/com/sap/hcp/cf/logging/common/request/RequestRecordTest.java

Lines changed: 4 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -1,12 +1,12 @@
11
package com.sap.hcp.cf.logging.common.request;
22

3+
import static org.hamcrest.MatcherAssert.assertThat;
34
import static org.hamcrest.Matchers.greaterThan;
45
import static org.hamcrest.Matchers.lessThanOrEqualTo;
56
import static org.hamcrest.core.Is.is;
67
import static org.hamcrest.core.IsNot.not;
78
import static org.hamcrest.core.IsNull.notNullValue;
89
import static org.hamcrest.core.IsNull.nullValue;
9-
import static org.junit.Assert.assertThat;
1010

1111
import java.io.IOException;
1212

@@ -21,13 +21,11 @@
2121
import com.sap.hcp.cf.logging.common.DoubleValue;
2222
import com.sap.hcp.cf.logging.common.Fields;
2323
import com.sap.hcp.cf.logging.common.Markers;
24-
import com.sap.hcp.cf.logging.common.request.RequestRecord;
25-
import com.sap.hcp.cf.logging.common.request.TestRequestRecord;
2624
import com.sap.hcp.cf.logging.common.request.RequestRecord.Direction;
2725

28-
public class TestRequestRecord extends AbstractTest {
26+
public class RequestRecordTest extends AbstractTest {
2927

30-
private final Logger logger = LoggerFactory.getLogger(TestRequestRecord.class);
28+
private final Logger logger = LoggerFactory.getLogger(RequestRecordTest.class);
3129
private RequestRecord rrec;
3230

3331
@Test
@@ -42,7 +40,7 @@ public void testDefaults() throws JSONObjectException, IOException {
4240
assertThat(getField(Fields.REQUEST_SIZE_B), is("-1"));
4341
assertThat(getField(Fields.REQUEST_RECEIVED_AT), not(nullValue()));
4442
assertThat(getField(Fields.REQUEST_RECEIVED_AT), not(nullValue()));
45-
assertThat(Double.valueOf(getField(Fields.RESPONSE_TIME_MS)), greaterThan(new Double(0.0)));
43+
assertThat(Double.valueOf(getField(Fields.RESPONSE_TIME_MS)), greaterThan(0.0d));
4644

4745
assertThat(getField(Fields.REQUEST), is(Defaults.UNKNOWN));
4846
assertThat(getField(Fields.REMOTE_IP), is(Defaults.UNKNOWN));

0 commit comments

Comments
 (0)