Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[close #404] use System.nanoTime() to calculate duration, cause System.currentTimeMillis() is not monotonic #402

Merged

Conversation

marsishandsome
Copy link
Collaborator

@marsishandsome marsishandsome commented Dec 14, 2021

Signed-off-by: marsishandsome marsishandsome@gmail.com

close #404

use System.nanoTime() to calculate duration, cause System.currentTimeMillis() is not monotonic

The performance between System.nanoTime() and System.currentTimeMillis() is almost the same.
see https://www.javaadvent.com/2019/12/measuring-time-from-java-to-kernel-and-back.html

@marsishandsome marsishandsome changed the title use System.nanoTime() to calculate duration, cause System.currentTimeMillis() is not monotonic [close #404] use System.nanoTime() to calculate duration, cause System.currentTimeMillis() is not monotonic Dec 14, 2021
@marsishandsome
Copy link
Collaborator Author

/run-all-tests

Copy link
Member

@zz-jason zz-jason left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

could use JMH to add a micro benchmark and show the result to tell the performance difference?

this.endMS = 0;
this.endNano = 0;
}

@Override
public void start() {
this.startMS = System.currentTimeMillis();
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we can remove the previous startMS and switch to nanoTime

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we will lose the time point information if removed.
System.nanoTime() can be only used to measure the difference of time.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

how about we use a specialized clock to calculate the difference of time more accurately without checking currentMillis() every time? I can optimize it after your PR is merged.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

fixed

…Millis() is not monotonic

Signed-off-by: marsishandsome <marsishandsome@gmail.com>
Signed-off-by: marsishandsome <marsishandsome@gmail.com>
Signed-off-by: marsishandsome <marsishandsome@gmail.com>
Signed-off-by: marsishandsome <marsishandsome@gmail.com>
Copy link
Member

@zz-jason zz-jason left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

Signed-off-by: marsishandsome <marsishandsome@gmail.com>
Signed-off-by: marsishandsome <marsishandsome@gmail.com>
Copy link
Member

@iosmanthus iosmanthus left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@zz-jason
Copy link
Member

/merge

@ti-srebot
Copy link
Collaborator

/run-all-tests

@ti-srebot
Copy link
Collaborator

@marsishandsome merge failed.

@zz-jason
Copy link
Member

@marsishandsome UT failed, PTAL:

[2021-12-15T16:12:40.405Z] java.lang.IllegalArgumentException: To use compareAndSet or putIfAbsent, please enable the config tikv.enable_atomic_for_cas.
[2021-12-15T16:12:40.406Z] 	at org.tikv.raw.RawKVClient.compareAndSet(RawKVClient.java:168)
[2021-12-15T16:12:40.406Z] 	at org.tikv.raw.RawKVClient.putIfAbsent(RawKVClient.java:150)
[2021-12-15T16:12:40.406Z] 	at org.tikv.raw.RawKVClient.putIfAbsent(RawKVClient.java:144)
[2021-12-15T16:12:40.406Z] 	at org.tikv.common.TiSession.warmUp(TiSession.java:151)
[2021-12-15T16:12:40.406Z] 	at org.tikv.common.TiSession.<init>(TiSession.java:119)
[2021-12-15T16:12:40.406Z] 	at org.tikv.common.TiSession.create(TiSession.java:166)
[2021-12-15T16:12:40.406Z] 	at org.tikv.raw.MetricsTest.twoTiSessionWithDifferentPort(MetricsTest.java:74)
[2021-12-15T16:12:40.406Z] 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2021-12-15T16:12:40.406Z] 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[2021-12-15T16:12:40.406Z] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2021-12-15T16:12:40.406Z] 	at java.lang.reflect.Method.invoke(Method.java:498)
[2021-12-15T16:12:40.406Z] 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[2021-12-15T16:12:40.406Z] 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[2021-12-15T16:12:40.406Z] 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[2021-12-15T16:12:40.406Z] 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[2021-12-15T16:12:40.406Z] 	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
[2021-12-15T16:12:40.406Z] 	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
[2021-12-15T16:12:40.406Z] 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
[2021-12-15T16:12:40.406Z] 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
[2021-12-15T16:12:40.406Z] 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[2021-12-15T16:12:40.406Z] 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[2021-12-15T16:12:40.406Z] 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[2021-12-15T16:12:40.406Z] 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[2021-12-15T16:12:40.406Z] 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[2021-12-15T16:12:40.406Z] 	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[2021-12-15T16:12:40.406Z] 	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:252)
[2021-12-15T16:12:40.406Z] 	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:141)
[2021-12-15T16:12:40.406Z] 	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:112)
[2021-12-15T16:12:40.406Z] 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2021-12-15T16:12:40.406Z] 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[2021-12-15T16:12:40.406Z] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2021-12-15T16:12:40.406Z] 	at java.lang.reflect.Method.invoke(Method.java:498)
[2021-12-15T16:12:40.406Z] 	at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189)
[2021-12-15T16:12:40.406Z] 	at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165)
[2021-12-15T16:12:40.406Z] 	at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85)
[2021-12-15T16:12:40.406Z] 	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:115)
[2021-12-15T16:12:40.406Z] 	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:75)
[2021-12-15T16:12:40.406Z] 162301 [main] INFO  org.tikv.common.TiSession  - warm up duration 8 ms
[2021-12-15T16:12:40.406Z] 162301 [main] INFO  org.tikv.common.TiSession  - TiSession initialized in RAW mode
[2021-12-15T16:12:40.407Z] 162301 [main] INFO  org.tikv.common.MetricsServer  - Metrics server on 12345 is stopped
[2021-12-15T16:12:40.407Z] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.349 sec
[2021-12-15T16:12:40.974Z]
[2021-12-15T16:12:40.974Z] Results :
[2021-12-15T16:12:40.974Z]
[2021-12-15T16:12:40.974Z] Failed tests:   rawPutIfAbsentTest(org.tikv.raw.CASTest)
[2021-12-15T16:12:40.974Z]
[2021-12-15T16:12:40.974Z] Tests in error:
[2021-12-15T16:12:40.974Z]   switchTiKVModeTest(org.tikv.common.importer.SwitchTiKVModeTest): Failed to init client for PD cluster.
[2021-12-15T16:12:40.974Z]   rawKVIngestTest(org.tikv.common.importer.RawKVIngestTest): Failed to init client for PD cluster.
[2021-12-15T16:12:40.974Z]   rawKVIngestTestWithTTL(org.tikv.common.importer.RawKVIngestTest): Failed to init client for PD cluster.
[2021-12-15T16:12:40.974Z]   rawKVSplitTest(org.tikv.common.importer.RegionSplitTest): Failed to init client for PD cluster.
[2021-12-15T16:12:40.974Z]   closeTest(org.tikv.common.TiSessionTest): Failed to init client for PD cluster.
[2021-12-15T16:12:40.974Z]   closeAwaitTerminationTest(org.tikv.common.TiSessionTest): Failed to init client for PD cluster.
[2021-12-15T16:12:40.974Z]   closeWithRunningTaskTest(org.tikv.common.TiSessionTest): Failed to init client for PD cluster.
[2021-12-15T16:12:40.974Z]   rawCASTest(org.tikv.raw.CASTest): key=107,101,121,95,97,116,111,109,105,99 expectedPrevValue=Optional.empty prevValue=Optional[<ByteString@98a954a size=5 contents="value">]
[2021-12-15T16:12:40.974Z]
[2021-12-15T16:12:40.974Z] Tests run: 63, Failures: 1, Errors: 8, Skipped: 0

@marsishandsome
Copy link
Collaborator Author

/run-all-tests

@marsishandsome marsishandsome merged commit 1405fe7 into tikv:master Dec 17, 2021
ti-srebot pushed a commit to ti-srebot/client-java that referenced this pull request Dec 17, 2021
Signed-off-by: ti-srebot <ti-srebot@pingcap.com>
@ti-srebot
Copy link
Collaborator

cherry pick to release-3.1 in PR #417

marsishandsome added a commit that referenced this pull request Dec 17, 2021
Signed-off-by: ti-srebot <ti-srebot@pingcap.com>

Co-authored-by: Liangliang Gu <marsishandsome@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

[BUG] SlowLog endTime may < startTime
5 participants