Do not depend on system clock

[jmcc0nn3ll]

migrated from Bugzilla #413788
status ASSIGNED severity minor in component server for 9.1.x
Reported in version 9.0.4 on platform All
Assigned to: Simone Bordet

On 2013-07-26 05:21:08 -0400, Mikhail Mazursky wrote:

Using System.currentTimeMillis() is not the best option to measure time intervals inside JVM. System.nanoTime() provides better precision and it do not depend on system clock (!).

E.g. QueuedThreadPool can use System.nanoTime() to measure timeouts and be immune to system clock adjustments (e.g. by NTPD).

If you decide to implement this enhancement, please thoroughly look at nanoTime() javadocs - there is a possibility of overflow if method is used incorrectly.

On 2013-09-05 05:49:24 -0400, Simone Bordet wrote:

Notes: System.nanoTime() is subject to NTP changes under 64-bit Linux, see http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6900441.

But yes, in general we should use System.nanoTime() everywhere.

On 2013-09-05 06:54:07 -0400, Mikhail Mazursky wrote:

JFYI there is a discussion about this bug happening right now on concurrency mailing list.
cs.oswego.edu/pipermail/concurrency-interest/2013-September/011759.html

[joakime]

Considering this implemented already, closing.

[sbordet]

Over a thousand usages of System.currentTimeMillis() around, so not done yet.

[stale]

This issue has been automatically marked as stale because it has been a full year without activit. It will be closed if no further activity occurs. Thank you for your contributions.

[joakime]

Current list in jetty-9.4.x (not including tests)

jetty-continuation/src/main/java/org/eclipse/jetty/continuation/FauxContinuation.java:404:        long expireAt = System.currentTimeMillis() + _timeoutMs;
jetty-continuation/src/main/java/org/eclipse/jetty/continuation/FauxContinuation.java:416:            wait = expireAt - System.currentTimeMillis();
jetty-deploy/src/main/java/org/eclipse/jetty/deploy/DeploymentManager.java:124:            this.stateTimestamps.put(node, Long.valueOf(System.currentTimeMillis()));
jetty-gcloud/jetty-gcloud-session-manager/src/main/java/org/eclipse/jetty/gcloud/session/GCloudSessionDataStore.java:532:        long now = System.currentTimeMillis();
jetty-gcloud/jetty-gcloud-session-manager/src/main/java/org/eclipse/jetty/gcloud/session/GCloudSessionDataStore.java:626:            .setFilter(CompositeFilter.and(PropertyFilter.gt(_model.getExpiry(), 0), PropertyFilter.le(_model.getExpiry(), System.currentTimeMillis())))
jetty-gcloud/jetty-gcloud-session-manager/src/main/java/org/eclipse/jetty/gcloud/session/GCloudSessionDataStore.java:633:            long start = System.currentTimeMillis();
jetty-gcloud/jetty-gcloud-session-manager/src/main/java/org/eclipse/jetty/gcloud/session/GCloudSessionDataStore.java:635:            LOG.debug("Expiry query no index in {}ms", System.currentTimeMillis() - start);
jetty-gcloud/jetty-gcloud-session-manager/src/main/java/org/eclipse/jetty/gcloud/session/GCloudSessionDataStore.java:657:        long now = System.currentTimeMillis();
jetty-gcloud/jetty-gcloud-session-manager/src/main/java/org/eclipse/jetty/gcloud/session/GCloudSessionDataStore.java:670:            long start = System.currentTimeMillis();
jetty-gcloud/jetty-gcloud-session-manager/src/main/java/org/eclipse/jetty/gcloud/session/GCloudSessionDataStore.java:672:            LOG.debug("Expiry query by index in {}ms", System.currentTimeMillis() - start);
jetty-gcloud/jetty-gcloud-session-manager/src/main/java/org/eclipse/jetty/gcloud/session/GCloudSessionDataStore.java:703:                long start = System.currentTimeMillis();
jetty-gcloud/jetty-gcloud-session-manager/src/main/java/org/eclipse/jetty/gcloud/session/GCloudSessionDataStore.java:705:                LOG.debug("Exists query by index in {}ms", System.currentTimeMillis() - start);
jetty-gcloud/jetty-gcloud-session-manager/src/main/java/org/eclipse/jetty/gcloud/session/GCloudSessionDataStore.java:731:                long start = System.currentTimeMillis();
jetty-gcloud/jetty-gcloud-session-manager/src/main/java/org/eclipse/jetty/gcloud/session/GCloudSessionDataStore.java:733:                LOG.debug("Exists query no index in {}ms", System.currentTimeMillis() - start);
jetty-gcloud/jetty-gcloud-session-manager/src/main/java/org/eclipse/jetty/gcloud/session/GCloudSessionDataStore.java:759:            return timestamp < System.currentTimeMillis();
jetty-hazelcast/src/main/java/org/eclipse/jetty/hazelcast/session/HazelcastSessionDataStore.java:150:        long now = System.currentTimeMillis();
jetty-hazelcast/src/main/java/org/eclipse/jetty/hazelcast/session/HazelcastSessionDataStore.java:272:            return sd.getExpiry() > System.currentTimeMillis(); //not expired yet
jetty-http/src/main/java/org/eclipse/jetty/http/HttpCookie.java:349:                DateGenerator.formatCookieDate(buf, System.currentTimeMillis() + 1000L * _maxAge);
jetty-http/src/main/java/org/eclipse/jetty/http/HttpCookie.java:405:                DateGenerator.formatCookieDate(buf, System.currentTimeMillis() + 1000L * _maxAge);
jetty-infinispan/infinispan-common/src/main/java/org/eclipse/jetty/session/infinispan/InfinispanSessionDataStore.java:145:        long now = System.currentTimeMillis();
jetty-infinispan/infinispan-common/src/main/java/org/eclipse/jetty/session/infinispan/InfinispanSessionDataStore.java:288:                        reference.set(sd.getExpiry() > System.currentTimeMillis()); //not expired yet
jetty-infinispan/infinispan-embedded-query/src/main/java/org/eclipse/jetty/session/infinispan/EmbeddedQueryManager.java:40:        return queryExpiredSessions(System.currentTimeMillis());
jetty-infinispan/infinispan-remote-query/src/main/java/org/eclipse/jetty/session/infinispan/RemoteQueryManager.java:65:        return queryExpiredSessions(System.currentTimeMillis());
jetty-io/src/main/java/org/eclipse/jetty/io/AbstractConnection.java:44:    private final long _created = System.currentTimeMillis();
jetty-io/src/main/java/org/eclipse/jetty/io/AbstractEndPoint.java:37:    private final long _created = System.currentTimeMillis();
jetty-io/src/main/java/org/eclipse/jetty/io/ConnectionStatistics.java:93:        long elapsed = System.currentTimeMillis() - connection.getCreatedTimeStamp();
jetty-jaspi/src/main/java/org/eclipse/jetty/security/jaspi/modules/DigestAuthModule.java:51:    protected long nonceSecret = this.hashCode() ^ System.currentTimeMillis();
jetty-jaspi/src/main/java/org/eclipse/jetty/security/jaspi/modules/DigestAuthModule.java:91:            long timestamp = System.currentTimeMillis();
jetty-jmh/src/main/java/org/eclipse/jetty/util/jmh/DateCacheBenchmark.java:68:        dateCache.formatNow(System.currentTimeMillis());
jetty-jmh/src/main/java/org/eclipse/jetty/util/jmh/DateCacheNoTick.java:183:        return formatNow(System.currentTimeMillis());
jetty-jmh/src/main/java/org/eclipse/jetty/util/jmh/DateCacheNoTickBenchmark.java:67:        dateCache.formatNow(System.currentTimeMillis());
jetty-jmh/src/main/java/org/eclipse/jetty/util/jmh/DateCacheSimpleDateFormat.java:231:        return formatNow(System.currentTimeMillis());
jetty-jmh/src/main/java/org/eclipse/jetty/util/jmh/DateCacheSimpleDateFormat.java:236:        return formatTick(System.currentTimeMillis());
jetty-jmh/src/main/java/org/eclipse/jetty/util/jmh/DateCacheSimpleDateFormatBenchmark.java:67:        dateCache.formatNow(System.currentTimeMillis());
jetty-maven-plugin/src/main/java/org/eclipse/jetty/maven/plugin/JettyRunDistro.java:574:        return Long.toString(random.nextLong() ^ System.currentTimeMillis(), 36).toUpperCase(Locale.ENGLISH);
jetty-maven-plugin/src/main/java/org/eclipse/jetty/maven/plugin/JettyRunForkedMojo.java:516:        return Long.toString(random.nextLong() ^ System.currentTimeMillis(), 36).toUpperCase(Locale.ENGLISH);
jetty-nosql/src/main/java/org/eclipse/jetty/nosql/mongodb/MongoSessionDataStore.java:342:        if (expiry.longValue() > 0 && expiry.longValue() < System.currentTimeMillis())
jetty-nosql/src/main/java/org/eclipse/jetty/nosql/mongodb/MongoSessionDataStore.java:353:        long now = System.currentTimeMillis();
jetty-openid/src/main/java/org/eclipse/jetty/security/openid/OpenIdCredentials.java:160:        long currentTimeSeconds = (long)(System.currentTimeMillis() / 1000F);
jetty-osgi/jetty-osgi-boot/src/main/java/org/eclipse/jetty/osgi/boot/utils/EventSender.java:77:            props.put("timestamp", System.currentTimeMillis());
jetty-overlay-deployer/src/main/java/org/eclipse/jetty/overlays/OverlayedAppProvider.java:824:        _loading = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/AbstractNCSARequestLog.java:210:                long now = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/CachedContentFactory.java:427:            _lastAccessed = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/CachedContentFactory.java:477:                _lastAccessed = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/ConnectorStatistics.java:83:            _connectionDurationStats.record(System.currentTimeMillis() - connection.getCreatedTimeStamp());
jetty-server/src/main/java/org/eclipse/jetty/server/ConnectorStatistics.java:196:        return start < 0 ? 0 : System.currentTimeMillis() - start;
jetty-server/src/main/java/org/eclipse/jetty/server/ConnectorStatistics.java:228:        _startMillis.set(System.currentTimeMillis());
jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java:1149:        long currentTime = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java:1160:        long latency = System.currentTimeMillis() - request.getTimeStamp();
jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java:1166:        long latency = System.currentTimeMillis() - request.getTimeStamp();
jetty-server/src/main/java/org/eclipse/jetty/server/DebugListener.java:190:        long now = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/HttpChannel.java:658:            timeStamp == 0 ? 0 : System.currentTimeMillis() - timeStamp);
jetty-server/src/main/java/org/eclipse/jetty/server/HttpChannel.java:664:        _request.setTimeStamp(System.currentTimeMillis());
jetty-server/src/main/java/org/eclipse/jetty/server/LowResourceMonitor.java:351:                setLowResourcesStarted(System.currentTimeMillis());
jetty-server/src/main/java/org/eclipse/jetty/server/LowResourceMonitor.java:356:            if (getMaxLowResourcesTime() > 0 && (System.currentTimeMillis() - getLowResourcesStarted()) > getMaxLowResourcesTime())
jetty-server/src/main/java/org/eclipse/jetty/server/ResourceService.java:752:                    response.addDateHeader(HttpHeader.DATE.asString(), System.currentTimeMillis());
jetty-server/src/main/java/org/eclipse/jetty/server/ResourceService.java:770:                response.addDateHeader(HttpHeader.DATE.asString(), System.currentTimeMillis());
jetty-server/src/main/java/org/eclipse/jetty/server/Server.java:312:        long now = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/ShutdownMonitor.java:285:                key = Long.toString((long)(Long.MAX_VALUE * Math.random() + this.hashCode() + System.currentTimeMillis()), 36);
jetty-server/src/main/java/org/eclipse/jetty/server/handler/AbstractHandlerContainer.java:165:            long stopBy = System.currentTimeMillis() + stopTimeout;
jetty-server/src/main/java/org/eclipse/jetty/server/handler/AbstractHandlerContainer.java:175:                        future.get(Math.max(1L, stopBy - System.currentTimeMillis()), TimeUnit.MILLISECONDS);
jetty-server/src/main/java/org/eclipse/jetty/server/handler/DebugHandler.java:119:        long now = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/handler/DefaultHandler.java:57:    final long _faviconModified = (System.currentTimeMillis() / 1000) * 1000L;
jetty-server/src/main/java/org/eclipse/jetty/server/handler/StatisticsHandler.java:106:            final long elapsed = System.currentTimeMillis() - request.getTimeStamp();
jetty-server/src/main/java/org/eclipse/jetty/server/handler/StatisticsHandler.java:131:        _statsStartedAt.set(System.currentTimeMillis());
jetty-server/src/main/java/org/eclipse/jetty/server/handler/StatisticsHandler.java:165:            start = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/handler/StatisticsHandler.java:186:            final long now = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/handler/StatisticsHandler.java:526:        return System.currentTimeMillis() - _statsStartedAt.get();
jetty-server/src/main/java/org/eclipse/jetty/server/jmx/ServerMBean.java:40:        startupTime = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/session/AbstractSessionDataStore.java:130:                        data.isDirty(), data.getLastSaved(), savePeriodMs, (System.currentTimeMillis() - lastSave));
jetty-server/src/main/java/org/eclipse/jetty/server/session/AbstractSessionDataStore.java:135:                    (data.isMetaDataDirty() && ((System.currentTimeMillis() - lastSave) >= savePeriodMs)))
jetty-server/src/main/java/org/eclipse/jetty/server/session/AbstractSessionDataStore.java:138:                    data.setLastSaved(System.currentTimeMillis());
jetty-server/src/main/java/org/eclipse/jetty/server/session/AbstractSessionDataStore.java:172:            _lastExpiryCheckTime = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/session/DefaultSessionIdManager.java:256:                        _random.setSeed(_random.nextLong() ^ System.currentTimeMillis() ^ seedTerm ^ Runtime.getRuntime().freeMemory());
jetty-server/src/main/java/org/eclipse/jetty/server/session/DefaultSessionIdManager.java:383:            _random.setSeed(_random.nextLong() ^ System.currentTimeMillis() ^ hashCode() ^ Runtime.getRuntime().freeMemory());
jetty-server/src/main/java/org/eclipse/jetty/server/session/FileSessionDataStore.java:155:        final long now = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/session/FileSessionDataStore.java:206:        long now = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/session/FileSessionDataStore.java:364:            long now = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/session/FileSessionDataStore.java:454:            return (expiry > System.currentTimeMillis()); //hasn't yet expired
jetty-server/src/main/java/org/eclipse/jetty/server/session/HouseKeeper.java:210:                if ((System.currentTimeMillis() % 2) == 0)
jetty-server/src/main/java/org/eclipse/jetty/server/session/JDBCSessionDataStore.java:762:            LOG.debug("Getting expired sessions at time {}", System.currentTimeMillis());
jetty-server/src/main/java/org/eclipse/jetty/server/session/JDBCSessionDataStore.java:764:        long now = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/session/JDBCSessionDataStore.java:913:                            return (expiry > System.currentTimeMillis()); //hasn't already expired
jetty-server/src/main/java/org/eclipse/jetty/server/session/Session.java:124:                    long now = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/session/Session.java:150:            schedule(calculateInactivityTimeout(System.currentTimeMillis()));
jetty-server/src/main/java/org/eclipse/jetty/server/session/Session.java:289:                long now = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/session/Session.java:318:        long now = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/session/SessionData.java:384:        return calcExpiry(System.currentTimeMillis());
jetty-server/src/main/java/org/eclipse/jetty/server/session/SessionHandler.java:231:        long now = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/session/SessionHandler.java:761:        long created = System.currentTimeMillis();
jetty-server/src/main/java/org/eclipse/jetty/server/session/SessionHandler.java:910:                if (session.isExpiredAt(System.currentTimeMillis()))
jetty-server/src/main/java/org/eclipse/jetty/server/session/SessionHandler.java:1179:        _sessionTimeStats.record(round((System.currentTimeMillis() - session.getSessionData().getCreated()) / 1000.0));
jetty-server/src/main/java/org/eclipse/jetty/server/session/SessionHandler.java:1282:        sessionInactivityTimerExpired(session, System.currentTimeMillis());
jetty-servlets/src/main/java/org/eclipse/jetty/servlets/ConcatServlet.java:72:        _lastModified = System.currentTimeMillis();
jetty-servlets/src/main/java/org/eclipse/jetty/servlets/DoSFilter.java:318:            final boolean overRateLimit = tracker.isRateExceeded(System.currentTimeMillis());
jetty-servlets/src/main/java/org/eclipse/jetty/servlets/DoSFilter.java:1280:            boolean hasRecentRequest = last != 0 && (System.currentTimeMillis() - last) < 1000L;
jetty-servlets/src/main/java/org/eclipse/jetty/servlets/HeaderFilter.java:93:                    long headerValue = System.currentTimeMillis() + header.getMsOffset();
jetty-servlets/src/main/java/org/eclipse/jetty/servlets/PushSessionCacheFilter.java:103:                            if (last != null && (System.currentTimeMillis() - last) < _associateDelay)
jetty-servlets/src/main/java/org/eclipse/jetty/servlets/PushSessionCacheFilter.java:152:        timestamps.put(uri, System.currentTimeMillis());
jetty-start/src/main/java/org/eclipse/jetty/start/FS.java:163:        FileTime now = FileTime.fromMillis(System.currentTimeMillis());
jetty-util/src/main/java/org/eclipse/jetty/util/DateCache.java:226:        return formatNow(System.currentTimeMillis());
jetty-util/src/main/java/org/eclipse/jetty/util/DateCache.java:231:        return formatTick(System.currentTimeMillis());
jetty-util/src/main/java/org/eclipse/jetty/util/MultiPartOutputStream.java:49:            Long.toString(System.currentTimeMillis(), 36);
jetty-util/src/main/java/org/eclipse/jetty/util/MultiPartWriter.java:46:            Long.toString(System.currentTimeMillis(), 36);
jetty-util/src/main/java/org/eclipse/jetty/util/log/StdErrLog.java:439:        long now = System.currentTimeMillis();

[olamy]

happy to work on that.
Should we use a pattern such (each change need to be reviewed)

System.currentTimeMillis()
->
TimeUnit.MILLISECONDS.convert(System.currentTimeMillis(), TimeUnit.NANOSECONDS) 

?

[gregw]

This can't be automatic.... a lot of these probably can be changed to use nanotime as they are just intervals, but we also do have real need for wall clock time. For example sessions that are persisted and/or migrated between nodes cannot use nanotime for expiry and have to use a real wall clock.

[sbordet]

We should also consider for Jetty 10 to use java.time rather than long to express GMT times.

[joakime]

A PMD rule to check for System.currentTimeMillis() could be created.
Each occurrence would need to be vetted. Either changed or PMD tagged as appropriate (via a comment before its use).

[stale]

This issue has been automatically marked as stale because it has been a full year without activity. It will be closed if no further activity occurs. Thank you for your contributions.

[github-actions]

This issue has been automatically marked as stale because it has been a
full year without activity. It will be closed if no further activity occurs.
Thank you for your contributions.

[gregw]

This is being progressively fixed (see #8067), but will leave open to track progress

[dennyac]

Checking if you're fine to accept a contribution to change from System.currentTimeMillis() to System.nanoTime() in the HttpChannel class

In the jvm/application instrumentation library dropwizard metrics, System.nanoTime is used in all scenarios. The only exception where we use System.currentTimeMillis() is to measure jetty request times as the start time is set by jetty.

If we can change setting the request time to use System.nanoTime(), we can be consistent in all scenarios.

Suggested implementations

• Use existing _timeStamp field, leverage System.nanoTime() and convert to milliseconds
• Add a new field in the Request class and set it to System.nanoTime() (Should be a backwards compatible change)

[sbordet]

@dennyac Request.setTimeStamp() should remain an epoch time, because it is used for example in request logs (so it must be a meaningful date).

It's not clear to me what the problem is?

[joakime]

Perhaps it need to be a separately tracked metric?

You could use an HttpChannel.Listener.onRequestBegin() to set a Request.attribute with the nanotime as well.

Finally, are you sure you want nanotime in the raw like that?
Are you handling the nanotime gotchas yourself?

[github-actions]

This issue has been automatically marked as stale because it has been a
full year without activity. It will be closed if no further activity occurs.
Thank you for your contributions.

[joakime]

Work completed