高并发下高效获取时间戳
背景
Java获取当前时间戳一般是通过System.currentTimeMillis()来获取。这是一个native方法,用于获取当前时间与1970年1月1日0点之间的差,虽然返回值的时间单位是毫秒,但该值的粒度取决于基础操作系统
看下HotSpot源码的hotspot/src/os/linux/vm/os_linux.cpp文件中,有一个javaTimeMillis()方法,这就是System.currentTimeMillis()的native实现
jlong os::javaTimeMillis() {
timeval time;
int status = gettimeofday(&time, NULL);
assert(status != -1, "linux error");
return jlong(time.tv_sec) * 1000 + jlong(time.tv_usec / 1000);
}
复制代码
可以看到:
-
调用gettimeofday()需要从用户态切换到内核态;
-
gettimeofday()的表现受Linux系统的计时器(时钟源)影响,在HPET计时器下性能尤其差;
-
系统只有一个全局时钟源,高并发或频繁访问会造成严重的争用。
HPET计时器性能较差的原因是会将所有对时间戳的请求串行执行。TSC计时器性能较好,因为有专用的寄存器来保存时间戳。缺点是可能不稳定,因为它是纯硬件的计时器,频率可变(与处理器的CLK信号有关)
可以用以下的命令查看时钟源:
cat /sys/devices/system/clocksource/clocksource0/available_clocksource # 查看全部支持的时钟源
cat /sys/devices/system/clocksource/clocksource0/current_clocksource # 查看当前使用的时钟源
复制代码
修改时钟源:
echo 'hpet' > /sys/devices/system/clocksource/clocksource0/current_clocksource
复制代码
解决方案
最常见的办法是用单个调度线程(守护线程)来按毫秒更新时间戳,相当于维护一个全局内存缓存。
其他线程取时间戳时相当于从内存取,不会再造成时钟资源的争用,代价就是牺牲了一些精确度。
代码如下:
package cn.hutool.core.date;
import java.sql.Timestamp;
import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.TimeUnit;
/**
* 系统时钟
* 高并发场景下System.currentTimeMillis()的性能问题的优化
* System.currentTimeMillis()的调用比new一个普通对象要耗时的多(具体耗时高出多少我还没测试过,有人说是100倍左右)
* System.currentTimeMillis()之所以慢是因为去跟系统打了一次交道
* 后台定时更新时钟,JVM退出时,线程自动回收
*/
public class SystemClock {
/** 时钟更新间隔,单位毫秒 */
private final long period;
/** 现在时刻的毫秒数 */
private volatile long now;
/**
* 构造
* @param period 时钟更新间隔,单位毫秒
*/
public SystemClock(long period) {
this.period = period;
this.now = System.currentTimeMillis();
scheduleClockUpdating();
}
/**
* 开启计时器线程
*/
private void scheduleClockUpdating() {
ScheduledExecutorService scheduler = Executors.newSingleThreadScheduledExecutor(runnable -> {
Thread thread = new Thread(runnable, "System Clock");
thread.setDaemon(true);
return thread;
});
scheduler.scheduleAtFixedRate(() -> now = System.currentTimeMillis(), period, period, TimeUnit.MILLISECONDS);
}
/**
* @return 当前时间毫秒数
*/
private long currentTimeMillis() {
return now;
}
//------------------------------------------------------------------------ static
/**
* 单例
*
*/
private static class InstanceHolder {
public static final SystemClock INSTANCE = new SystemClock(1);
}
/**
* @return 当前时间
*/
public static long now() {
return InstanceHolder.INSTANCE.currentTimeMillis();
}
/**
* @return 当前时间字符串表现形式
*/
public static String nowDate() {
return new Timestamp(InstanceHolder.INSTANCE.currentTimeMillis()).toString();
}
}
复制代码
- 采用守护线程作为定时任务:守护线程会随着用户线程的结束而结束,无需单独处理关闭问题(程序结束时,守护线程可以立即关闭,不同于用户线程,比如数据库操作线程,正在插入数据的时候,程序结束了,此时必须正常正确的优雅结束插入数据线程),为其他用户线程提供服务支持
- 定时任务每毫秒调用一次System.currentTimeMillis(),并存入内存中,采用volatile保证不同线程间的可见性(由于采用了volatile所以禁止了重排序,导致CPU三级缓存无法用到,多线程单次调用下可能性能不佳,后面讲到)
- 单例模式,防止new多个对象,导致起多个定时获取时间戳的守护线程
使用
- 根据时间戳进行耗时分析或者只是获取当前时间的场景
- 日志打印(access.log,log4j日志)中日志时间的写入
- new Date()获取当前时间的场景
其中日志的时间打印
LOG4J篇:
我们采用Lombok的日志注解,启动一个单元测试,走一下看看我们平常用的日志框架是如何注入时间戳的
如上图,进入断点,选择步入方法(进入方法内部)
接着步入
如上图,选择步过(跳过其他方法,进入该方法的下一步)
如上图,选择步入后,选择要步入的方法
接着按照次方法一步一步走......
走到上图这里后,我们发下这边会返回一个logEvent,这个logEvent涉及到时间戳
所以这个logEventFactory对象是怎么初始化的就很重要
如上图,我们当前类搜索logEventFactory,结合构造函数已经静态类,可以看到这个logEnvetFactory工厂类是通过log4j的配置文件log4j2.component.properties获取,进行初始化
如下图,看下默认的LogEvent工厂
如下图,可以看到纳秒时间的获取默认是获取一个假的时间,时间戳是0,无需关注
我们需要关注CLOCK这个对象的获取(通过工厂类获取)
我们看下getStringProperty方法,如下图,通过environment的get获取,我们来看下这个get方法
如上图,我们可以看到,除了在配置文件(log4j2.component.properties)外,这个属性的key(log4j.Clock)是可以通过java启动变量来注入的,类似 -Dlog4j.Clock=自定义的类路径
之后,我们需要实现Clock的currentTimeMillis接口,如下图
如下图,只需实现这个接口就好,之后把这个类路径注入到启动参数中,log4j就会用这个获取时间的方式
public class SystemLogClock implements Clock {
@Override
public long currentTimeMillis() {
// 改为从内存获取
return SystemClock.now();
}
}
复制代码
除此之外就没有了吗,当然不是,还需要注意一个地方,我们接着之前LoggerConfig的断点往下走,如下图
如上图,看到Layout,大家应该不陌生,通过继承AbstractStringLayout实现toSerializable方法来进行格式化输出。
此外还需要 @Plugin注解进行注册
@Plugin(name = "CustomLayout", category = Node.CATEGORY, elementType = Layout.ELEMENT_TYPE, printObject = true)
复制代码
还需要在log4j2-dev.xml这样的配置文件中进行注入,类似
复制代码
在自定义的CustomLayout中实现toSerializable时,我们可以使用从内存中获取的时间戳进行赋值
ACCESS.LOG篇:
同log4j的分析,我们需要打断点来分析注入时间戳的地方,以undertow为例
我们知道undertow有个配置文件的地方,类似:
server:
port: 8888
undertow:
# 以下的配置会影响buffer,这些buffer会用于服务器连接的IO操作,有点类似netty的池化内存管理
# 每块buffer的空间大小,越小的空间被利用越充分
buffer-size: 1024
# 是否分配的直接内存
direct-buffers: true
accesslog:
dir: "/logs"
enabled: true
pattern: '%h %l %u %t "%r" %s %b'
prefix: "custom.access.log"
suffix: ""
threads:
worker: 4096
复制代码
观察上图的pattern,我们注意到有个%t 这个占位符,这个正好对应请求的时间戳的位置,类似
0:0:0:0:0:0:0:1 - - 2021-04-08 16:01:21.867 "GET /custom?token=aaaa HTTP/1.1" 200 1316
复制代码
那么可以自定义一个占位符来更改获取时间戳的逻辑
结合我的上一篇文章 Undertow容器在Springboot中如何自定义修改文件名 juejin.cn/post/693060… 可以知道修改获取时间戳的地方
我们只需要继承ExchangeAttribute接口,实现readAttribute方法就可以
再来看下builders的获取,如下图:
同样我们可以参照io.undertow.attribute.DateTimeAttribute 来进行重写,修改时间戳的获取方式,并自定义占位符前缀 %{customTime, 如下图:
package com.xiaoju.manhattan.messenger.notice.api.config.undertow;
import cn.hutool.core.date.SystemClock;
import io.undertow.attribute.ExchangeAttribute;
import io.undertow.attribute.ExchangeAttributeBuilder;
import io.undertow.attribute.ReadOnlyAttributeException;
import io.undertow.server.HttpServerExchange;
import io.undertow.util.DateUtils;
import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.TimeZone;
/**
* The current time
*
* @author Stuart Douglas
*/
public class CustomDateTimeAttribute implements ExchangeAttribute {
public static final String CUSTOM_TIME = "%{customTime,";
public static final ExchangeAttribute INSTANCE = new CustomDateTimeAttribute();
private final String dateFormat;
private final ThreadLocal cachedFormat;
private CustomDateTimeAttribute() {
this.dateFormat = null;
this.cachedFormat = null;
}
public CustomDateTimeAttribute(final String dateFormat) {
this(dateFormat, null);
}
public CustomDateTimeAttribute(final String dateFormat, final String timezone) {
this.dateFormat = dateFormat;
this.cachedFormat = ThreadLocal.withInitial(() -> {
final SimpleDateFormat format = new SimpleDateFormat(dateFormat);
if (timezone != null) {
format.setTimeZone(TimeZone.getTimeZone(timezone));
}
return format;
});
}
@Override
public String readAttribute(final HttpServerExchange exchange) {
if (dateFormat == null) {
return DateUtils.toCommonLogFormat(new Date(SystemClock.now()));
} else {
final SimpleDateFormat dateFormat = this.cachedFormat.get();
return dateFormat.format(new Date(SystemClock.now()));
}
}
@Override
public void writeAttribute(final HttpServerExchange exchange, final String newValue)
throws ReadOnlyAttributeException {
throw new ReadOnlyAttributeException("Date time", newValue);
}
public static final class Builder implements ExchangeAttributeBuilder {
@Override
public String name() {
return "Date Time";
}
@Override
public ExchangeAttribute build(final String token) {
if (token.startsWith(CUSTOM_TIME) && token.endsWith("}")) {
return new CustomDateTimeAttribute(
token.substring(CUSTOM_TIME.length(), token.length() - 1));
}
return null;
}
@Override
public int priority() {
return 0;
}
}
}
复制代码
接着仿照SPI的方式,进行注入,如下图
custom.undertow.CustomDateTimeAttribute$Builder
复制代码
最后修改下我们的pattern,更改%t 为 %{customTime,yyyy-MM-dd HH:mm:ss.SSS}
pattern: '%h %l %u %{customTime,yyyy-MM-dd HH:mm:ss.SSS} "%r" %s %b'
复制代码
这样就可以实现时间戳获取的替换
性能测试
为了测试性能,写了一个单元测试
package custom;
import cn.hutool.core.date.SystemClock;
import com.github.houbb.junitperf.core.annotation.JunitPerfConfig;
import java.util.concurrent.CompletableFuture;
import lombok.extern.slf4j.Slf4j;
import org.junit.Test;
/**
* @Description 系统时钟并发测试
*/
@Slf4j
public class SystemClockTest {
/**
* 起2000个线程进行获取当前时间戳(native调用)
*/
@Test
@JunitPerfConfig(threads = 2000)
public void testSystemTime() {
System.currentTimeMillis();
}
/**
* 起2000个线程进行获取当前时间戳(内存调用)
*/
@Test
@JunitPerfConfig(threads = 2000)
public void testSystemClockMultiThread() {
SystemClock.now();
}
/**
* 测试log4j日志写入流程
*/
@Test
public void testLog() {
log.info("欧拉欧拉欧拉欧拉欧拉欧拉欧拉欧拉");
}
@Test
public void systemClockTest() throws InterruptedException {
// 预热
long ready = SystemClock.now();
int num = 10000;
long start0 = System.currentTimeMillis();
batchExe(num, () -> {
for (int i = 0; i < 10; i++) {
SystemClock.now();
}
});
long end0 = System.currentTimeMillis();
System.out.println("pre ready SystemClock Time:" + (end0 - start0) + "毫秒");
// SystemClock
long start1 = System.currentTimeMillis();
batchExe(num, () -> {
for (int i = 0; i < num; i++) {
SystemClock.now();
}
});
long end1 = System.currentTimeMillis();
System.out.println("SystemClock Time:" + (end1 - start1) + "毫秒");
// currentTimeMillis
long start2 = System.currentTimeMillis();
batchExe(num, () -> {
for (int i = 0; i < num; i++) {
System.currentTimeMillis();
}
});
long end2 = System.currentTimeMillis();
System.out.println("CurrentTimeMillis Time:" + (end2 - start2) + "毫秒");
}
private void batchExe(int num, Runnable runnable) {
CompletableFuture[] futures = new CompletableFuture[num];
for (int i = 0; i < num; i++) {
futures[i] = CompletableFuture.runAsync(runnable);
}
CompletableFuture.allOf(futures).join();
}
}
复制代码
当有1万个线程并发调用,每个线程获取一万次时间戳的时候(进行预热,排除对象初始化,线程初始化占用的时间),如下图:
可以看到有明细的性能差距,大概有10倍的差距
当有50个线程直接调用时(native调用):
[INFO] [2021-04-02 17:17:48.301] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - --------------------------------------------------------
[INFO] [2021-04-02 17:17:48.303] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Started at: 2021-04-02 17:16:48.177
[INFO] [2021-04-02 17:17:48.303] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Invocations: 67108914
[INFO] [2021-04-02 17:17:48.304] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Success: 67108914
[INFO] [2021-04-02 17:17:48.304] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Errors: 0
[INFO] [2021-04-02 17:17:48.304] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Thread Count: 50
[INFO] [2021-04-02 17:17:48.305] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Warm up: 0ms
[INFO] [2021-04-02 17:17:48.305] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Execution time: 60000ms
[INFO] [2021-04-02 17:17:48.305] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Throughput: 1118481/s (Required: -1/s) - PASSED
[INFO] [2021-04-02 17:17:48.305] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Memory cost: 16byte
[INFO] [2021-04-02 17:17:48.428] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Min latency: 1.0E-6ms (Required: -1.0ms) - PASSED
[INFO] [2021-04-02 17:17:48.512] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Max latency: 272.46924ms (Required: -1.0ms) - PASSED
[INFO] [2021-04-02 17:17:48.683] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Avg latency: 1.922781E-4ms (Required: -1.0ms) - PASSED
[INFO] [2021-04-02 17:17:48.683] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - --------------------------------------------------------
复制代码
当有50个线程直接调用时(内存调用)
[INFO] [2021-04-02 17:19:08.016] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - --------------------------------------------------------
[INFO] [2021-04-02 17:19:08.017] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Started at: 2021-04-02 17:18:07.834
[INFO] [2021-04-02 17:19:08.017] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Invocations: 67108914
[INFO] [2021-04-02 17:19:08.017] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Success: 67108914
[INFO] [2021-04-02 17:19:08.018] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Errors: 0
[INFO] [2021-04-02 17:19:08.018] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Thread Count: 50
[INFO] [2021-04-02 17:19:08.018] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Warm up: 0ms
[INFO] [2021-04-02 17:19:08.019] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Execution time: 60000ms
[INFO] [2021-04-02 17:19:08.019] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Throughput: 1118481/s (Required: -1/s) - PASSED
[INFO] [2021-04-02 17:19:08.019] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Memory cost: 16byte
[INFO] [2021-04-02 17:19:08.112] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Min latency: 1.0E-6ms (Required: -1.0ms) - PASSED
[INFO] [2021-04-02 17:19:08.196] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Max latency: 179.08081ms (Required: -1.0ms) - PASSED
[INFO] [2021-04-02 17:19:08.368] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Avg latency: 1.3518152E-4ms (Required: -1.0ms) - PASSED
[INFO] [2021-04-02 17:19:08.369] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - --------------------------------------------------------
复制代码
但是当1万个线程并发调用,每个线程获取一次时间戳的时候,如下图:
当有2000个线程直接调用时(native调用)
[INFO] [2021-04-02 17:30:48.815] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - --------------------------------------------------------
[INFO] [2021-04-02 17:30:48.816] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Started at: 2021-04-02 17:27:32.223
[INFO] [2021-04-02 17:30:48.817] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Invocations: 67110864
[INFO] [2021-04-02 17:30:48.817] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Success: 67110864
[INFO] [2021-04-02 17:30:48.817] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Errors: 0
[INFO] [2021-04-02 17:30:48.817] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Thread Count: 2000
[INFO] [2021-04-02 17:30:48.817] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Warm up: 0ms
[INFO] [2021-04-02 17:30:48.818] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Execution time: 60000ms
[INFO] [2021-04-02 17:30:48.818] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Throughput: 1118514/s (Required: -1/s) - PASSED
[INFO] [2021-04-02 17:30:48.818] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Memory cost: 16byte
[INFO] [2021-04-02 17:30:48.926] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Min latency: 1.0E-6ms (Required: -1.0ms) - PASSED
[INFO] [2021-04-02 17:30:49.028] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Max latency: 99.11504ms (Required: -1.0ms) - PASSED
[INFO] [2021-04-02 17:30:49.209] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] - Avg latency: 1.8578941E-4ms (Required: -1.0ms) - PASSED
[INFO] [2021-04-02 17:30:49.209] [c.x.m.m.n.a.s.SystemClockTest.testSystemTime] -
复制代码
当有2000个线程直接调用时(内存调用)
[INFO] [2021-04-02 17:34:26.853] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - --------------------------------------------------------
[INFO] [2021-04-02 17:34:26.856] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Started at: 2021-04-02 17:31:14.774
[INFO] [2021-04-02 17:34:26.856] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Invocations: 67110864
[INFO] [2021-04-02 17:34:26.856] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Success: 67110864
[INFO] [2021-04-02 17:34:26.856] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Errors: 0
[INFO] [2021-04-02 17:34:26.857] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Thread Count: 2000
[INFO] [2021-04-02 17:34:26.857] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Warm up: 0ms
[INFO] [2021-04-02 17:34:26.858] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Execution time: 60000ms
[INFO] [2021-04-02 17:34:26.858] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Throughput: 1118514/s (Required: -1/s) - PASSED
[INFO] [2021-04-02 17:34:26.859] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Memory cost: 16byte
[INFO] [2021-04-02 17:34:26.991] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Min latency: 1.0E-6ms (Required: -1.0ms) - PASSED
[INFO] [2021-04-02 17:34:27.089] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Max latency: 167.16472ms (Required: -1.0ms) - PASSED
[INFO] [2021-04-02 17:34:27.293] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] - Avg latency: 3.9316338E-4ms (Required: -1.0ms) - PASSED
[INFO] [2021-04-02 17:34:27.293] [c.x.m.m.n.a.s.SystemClockTest.testSystemClockMultiThread] -
复制代码
可以看到,从内存获取反而不如直接native调用速度快
原因是:通过volatile修饰的变量,无法重排序,也无法使用写缓冲和三级缓存,为了保证可见性,只能通过主内存来获取
我们知道三级缓存是SRAM缓存,速度要比内存缓存快很多,一级缓存的话,平均速度是1ns,三级缓存也有12ns左右,而内存速度要差很多
所以多线程调用下,可能还不如直接的系统调用,例如TSC计时器性能较好,因为有专用的寄存器来保存时间戳
注意事项
- 在System.currentTimeMillis()的效率没有影响程序整体的效率时,就完全没有必要做这种优化,这只是为极端情况准备的
- 如果要改造获取时间戳的方式,那么日志,业务部分等的地方都需要替换下