QNAP 新版 License Center 校验流程逆向

2024 年 11 月 11 日2024 年 11 月 14 日 by Orange

最近新添置了两个支持 ONVIF 协议的摄像头，想使用 QNAP 的 QVR 进行录像。但是打开 QVR 发现，只能添加两个通道，后续新的通道需要按年付费解锁。依稀记得原先是有 8 个免费通道可用的，于是打开官方文档，发现：

系统	软件	授权
QTS	QVR Pro	自带 8 通道
QTS	QVR Elite	自带 2 通道
QuTS hero	QVR Elite	自带 2 通道

原来官方提供的 8 通道 QVR Pro 只支持 QTS 系统，不支持基于 ZFS 的 QuTS hero 系统。既然官方不支持，那只能自己动手了。

TL; DR

GPT 太好用了，大大提升逆向效率
新版校验用的 Public Key 经过简单的凯撒密码加密后打包在 libqlicense.so 中
LIF 文件的 floating 相关字段需要干掉，否则会联机校验

激活流程

在研究的过程中，发现已有前人详细分析了激活流程的各个步骤，分析了各个文件的存储、编码、加密、验证格式，并编写了相关脚本和代码。具体文章在这里，此处不多做赘述：

https://jxcn.org/2022/03/qnap-license

尝试动手

参考文章，尝试在 NAS 上进行操作。结果发现，找不到文章中提及的 qlicense_public_key.pem 文件，全盘搜索后发现依然找不到该文件。查看文章评论发现，似乎官方在 23 年左右修改了一次校验逻辑，去掉了该文件。所有 23 年之后发布的版本，都无法使用替换 key 文件的方式进行激活。

重新分析

虽然官方修改了相关逻辑，但是有前人经验参考，还是很快发现了关键所在。

先用 IDA 打开 qlicense_tool ，找到离线激活的处理函数，发现对输入进行简单处理后直接调用了 qcloud_license_offline_activate 函数，位于 libqlicense.so 动态链接库中。这个函数在几层调用之后，最终调用了 qcloud_license_internal_verify 函数，对 LIF 文件的签名进行了计算。

由于静态分析不太容易理清逻辑，于是上 GDB 准备直接调试。找了下发现 MyQNAP Repo 里有编译好的 GDB，但是安装却失败了。研究了下发现是作者把 X86 和 X41 的链接搞反了。X86 下载到的包是 X41 的，导致安装失败。于是手动下载了正确的包之后安装，一切顺利。

通过 gdb 调试发现，qcloud_license_internal_verify 函数的第一个入参就是校验用的 Public Key，打出来长这样：

通过 hook fopen 函数，想找到这个 key 存储在哪个文件，但是发现并没有结果。于是想到，这段 key 可能被打进了 so 文件本身，于是通过 Strings 搜索，但是依然没有找到相关字符串。

一筹莫展之际，在调用链路上乱点，突然注意到这样一段奇怪的代码（IDA 还原得出）：

    while ( 1 )
    {
      result[v3] = (v1[v3] + 95) % 128;
      if ( ++v3 == 359 )
        break;
      result = (_BYTE *)*a1;
    }

多看两眼之后意识到，这就是凯撒密码。（虽然凯撒密码现在看来其实更应该算是编码而非加密，但是考虑到确实有相关定义，因此后续均表述为加密和解密。）也就是说，之所以在 Strings 内找不到相关字符串，是因为写入的是通过凯撒密码加密后的字符串。于是把这段丢给 GPT，让它写个加密和解密的代码：

# -*- coding: utf-8 -*-

def decode(input_string):
    result = []
    for char in input_string:
        # 将每个字符的 ASCII 值加 95，然后对 128 取模
        encoded_char = (ord(char) + 95) % 128
        result.append(chr(encoded_char))
    return ''.join(result)

def encode(encoded_string):
    result = []
    for char in encoded_string:
        # 逆向解码：恢复原始字符
        decoded_char = (ord(char) - 95) % 128
        result.append(chr(decoded_char))
    return ''.join(result)

original_text = """-----BEGIN PUBLIC KEY-----
MHYwEAYHKoZIzj0CAQYFK4EEACIDYgAEDJcPoMIFyYDlhTUzNSeT/+3ZKcByILoI
Fw8mLv07Hpy2I5qgAGQu66vF3VUjFKgpDDFKVER9jwjjmXUOpoCXX4ynvFUpEM25
ULJE86Z6WjcLqyG03Mv6d3GPYNl/cJYt
-----END PUBLIC KEY-----"""
encoded_text = encode(original_text)
decoded_text = decode(encoded_text)

print("Original:", original_text)
print("Encoded:", encoded_text)
print("Decoded:", decoded_text)

跑了一下，得到实际存储的字符串：

NNNNNcfhjoAqvcmjdAlfzNNNNN+niz\u0018fbzil\u0010{j\u001b\u000bQdbrzglUffbdjez\bbfek\u0004q\u0010njg\u001aze\r\tuv\u001bot\u0006uPLT{l\u0004c\u001ajm\u0010j+g\u0018Y\u000em\u0017QXi\u0011\u001aSjV\u0012\bbhr\u0016WW\u0017gTwv\u000bgl\b\u0011eeglwfsZ\u000b\u0018\u000b\u000b\u000eyvp\u0011\u0010dyyU\u001a\u000f\u0017gv\u0011fnSV+vmkfYW{Wx\u000b\u0004m\u0012\u001ahQTn\u0017W\u0005Thqzo\rP\u0004kz\u0015+NNNNNfoeAqvcmjdAlfzNNNNN

由于开头和结尾的 ----- 会被加密为 NNNNN 因此直接在 Strings 中搜索，顺利定位到相关资源，位于 .rodata 段 38B40 的位置，长度 212。

接下来操作就简单了，生成一对新的 key 之后，直接替换指定位置即可。注意，由于长度是写死在代码里的，因此二者必须等长，否则可能会出现无法预料的错误。

再丢给 GPT 写个十六进制替换的脚本：

# -*- coding: utf-8 -*-

import binascii

def hex_to_bytes(hex_str):
    """将16进制字符串转换为字节数据。"""
    return binascii.unhexlify(hex_str)

def patch_file(file_path, search_hex, replace_hex):
    # 将16进制模式转换为字节数据
    search_bytes = hex_to_bytes(search_hex)
    replace_bytes = hex_to_bytes(replace_hex)
    
    # 检查替换块的长度是否匹配
    if len(search_bytes) != len(replace_bytes):
        raise ValueError("Length mismatch! 搜索模式和替换内容长度必须相同！")

    # 读取文件内容
    with open(file_path, "rb") as f:
        data = f.read()

    # 查找并替换内容
    patched_data = data.replace(search_bytes, replace_bytes)

    # 如果没有找到匹配的内容
    if data == patched_data:
        print("No Match. 没有找到匹配的内容。")
    else:
        # 将修改后的内容写回文件
        with open(file_path, "wb") as f:
            f.write(patched_data)
        print("Patch success. 文件已成功更新。")

# 使用示例
file_path = "libqlicense.so"           # 需要打补丁的文件路径
old_hex = "4e4e4e4e4e6366686a6f417176636d6a64416c667a4e4e4e4e4e2b6e697a1866627a696c107b6a1b0b516462727a676c55666662646a657a086266656b0471106e6a671a7a650d0975761b6f740675504c547b6c04631a6a6d106a2b6718590e6d17515869111a536a56120862687216575717675477760b676c08116565676c7766735a0b180b0b0e7976701110647979551a0f17677611666e53562b766d6b6659577b57780b046d121a6851546e1757055468717a6f0d50046b7a152b4e4e4e4e4e666f65417176636d6a64416c667a4e4e4e4e4e"              # 要搜索的16进制字符串
new_hex = "4e4e4e4e4e6366686a6f417176636d6a64416c667a4e4e4e4e4exxx4e4e4e4e4e666f65417176636d6a64416c667a4e4e4e4e4e"             # 替换为的16进制字符串

# 执行替换操作
patch_file(file_path, old_hex, new_hex)

这里使用 Hex Encoding 的原因是加密后的字符串存在一些非 ASCII 字符。

替换后，用原作者的相关脚本和工具，生成了一个 LIF，尝试使用 qlicense_tool 激活。此时发现，激活死活失败，但是调试发现 verify 实际已经过了。研究了好久之后，发现是 Console Management 工具导致的。由于 qlicense_tool 在激活过程中会运行被激活服务的脚本检测 License 正确性，而 Console Management 拦截了相关命令，导致返回包不是合法的 json，导致失败。在系统设置内关闭 Console Management 后，激活成功。

检测报错

本以为到此激活就成功了。结果打开许可证中心之后，发现许可证无效了。查阅相关日志，发现许可证中心发送了一个 POST 请求到 https://license.myqnapcloud.io/v1.1/license/device/installed ，然后报错许可不属于该设备，然后将许可改为失效。

阅读原作者相关文章，结合代码，发现是因为原作者是为了 QuTS Cloud 设计的代码，由于 Cloud 版没有离线激活功能，所以会定期刷新 Token，这里一刷新就发现许可有问题了。于是修改代码，将 LIF 内的 floating 相关字段全部干掉。包括：

FloatingUUID
FloatingToken
LicenseCheckPeriod

重新生成 LIF 文件，再次激活，已经不会向 myqnapcloud 验证激活信息了。

OpenResty AES 函数密钥生成原理

2024 年 2 月 1 日2024 年 2 月 1 日 by Orange

最近遇到一个场景，需要在 OpenResty 里使用 AES 对数据进行加密。但是看了一下官方提供的 AES 库，如果数据密码的话，并没有返回实际使用的 key 和 IV，因此查看了一下源码，研究了一下 key 生成的方式，方便其他语言使用。

密钥生成逻辑的核心代码在这：

function _M.new(self, key, salt, _cipher, _hash, hash_rounds, iv_len, enable_padding)

...

    local _hash = _hash or hash.md5
    local hash_rounds = hash_rounds or 1

...

        if C.EVP_BytesToKey(_cipher.method, _hash, salt, key, #key,
                            hash_rounds, gen_key, gen_iv)
            ~= _cipherLength
        then
            return nil, "failed to generate key and iv"
        end
end

其中最核心的部分就是使用了 EVP_BytesToKey 这个函数，进行密钥扩展。这个函数是 OpenSSL 库提供的函数，相关说明在这：

https://www.openssl.org/docs/man3.1/man3/EVP_BytesToKey.html

注意！该函数并不安全！一般不建议在生产中使用该函数！应当使用安全的密钥衍生函数（KDF）！

阅读文档，该函数的主要做法就是对提供的密码进行 hash，如果长度不够 key 或 iv 的要求，则继续进行 hash，直到长足足够为止。

第一轮 hash 直接拼接给定的密码和 salt，从第二轮开始，则将上一轮的结果附加在密码和 salt 前，然后再次进行 hash 操作。注意这里从第二轮开始附加的上一轮结果是二进制结果，如果希望手动使用工具计算的话，需要将 hex 编码或 base64 编码后的结果先进行解码，再附加在输入前。

用 Go 模拟这个过程的代码如下：

package main

import (
    "crypto/sha256"
    "fmt"
)

// EVPBytesToKey 模拟 OpenSSL EVP_BytesToKey 方法
func EVPBytesToKey(password, salt []byte, keyLen, ivLen int) (key, iv []byte) {
    var (
        concatenatedHashes []byte
        previousHash       []byte
        currentHash        []byte
        hash               = sha256.New()
    )

    for len(concatenatedHashes) < keyLen+ivLen {
        hash.Reset()

        // 如果不是第一轮，将上一轮的哈希值加到当前哈希的输入中
        if previousHash != nil {
            hash.Write(previousHash)
        }

        // 加入密码和盐值
        hash.Write(password)
        hash.Write(salt)

        // 当前哈希
        currentHash = hash.Sum(nil)

        // 添加到累积哈希中
        concatenatedHashes = append(concatenatedHashes, currentHash...)

        // 为下一轮准备
        previousHash = currentHash
    }

    // 提取密钥和 IV
    key = concatenatedHashes[:keyLen]
    iv = concatenatedHashes[keyLen : keyLen+ivLen]
    return key, iv
}

func main() {
    password := []byte("password")
    salt := []byte("salt")
    keyLen := 32 // AES-256 需要的密钥长度
    ivLen := 16  // AES 的 IV 长度

    key, iv := EVPBytesToKey(password, salt, keyLen, ivLen)
    fmt.Printf("Key: %x\nIV: %x\n", key, iv)
}

无痛解决 TeslaMate 访问 OpenStreetMap API 的问题

2023 年 12 月 9 日2023 年 12 月 9 日 by Orange

TeslaMate 是一款特斯拉汽车专用的增强工具，使用了破解的官方 App 的 API，将车机记录的大量信息进行了导出和展示，极大的增强了特斯拉车主的使用体验。

但是由于一些原因，中国特斯拉的汽车的数据都是存放在中国大陆，且不允许境外 IP 访问。因此，中国车主想要使用 TeslaMate，则必须在境内部署相关的服务。

不过，境内部署虽然可以解决访问 Tesla API 的问题，却也带来了新的问题，就是调用境外 API 的时候会出现错误，导致部分功能无法使用。

具体来说，TeslaMate 使用了 OpenStreetMap 提供的 API，用来将经纬度坐标转换为地名。然而，OpenStreetMap 的域名在境内是无法访问的，因此会导致解析坐标点的时候出现失败，导致在 Grafana 的 Drives（行程）面板不显示行程的起止地址。

为了解决这个问题，我首先想到了设置 http_proxy 等环境变量的方式。但是搜索之后发现，似乎 TeslaMate 并不会读区这几个环境变量，因此无法使用这种方式强制走代理访问相关 API。而且，由于 Tesla 本身的 API 不能走代理访问，必须使用中国 IP 访问，因此如果要使用这种方式的话，还需要配置 Proxy 的分流策略，非常麻烦。

综合考虑各种方案，我最终选择了 sniproxy 的方式。sniproxy 是允许在不解密流量本身的情况下，进行 SSL/TLS 流量转发的方案。使用 sniproxy 时，只需要将目标域名的 IP 强制指向 sniproxy 的 IP 地址（如修改 /etc/hosts），既可以完成代理。

方案一：直接在本地运行 sniproxy

优点：不占用母鸡的 443 端口，不影响现有服务
缺点：配置较为繁琐，需要两个额外的容器互相配合

考虑到搭建 sniproxy 需要占用一个 IP 的 443 端口，因此我决定在 docker compose 内增加 sniproxy 的相关容器，来做到不占用母鸡的 443 端口的目的。由于 sniproxy 是运行在 TeslaMate 同一台机器上的，因此还需要一个额外的代理来将流量转发出去。这一步有很多方案，使用 warp+、ss、v2 等均可实现，我选择使用 v2 的方案。

最终修改后的 docker-compose.yaml 新增的内容如下：

  sniproxy:
    image: sniproxy
    restart: always
    command: ./sniproxy
    depends_on:
      - xray
    networks:
      default:
        aliases:
          - nominatim.openstreetmap.org

  xray:
    image: teddysun/xray:latest
    restart: always
    volumes:
      - ./xray:/etc/xray

其中，sniproxy 镜像是对 https://github.com/XIU2/SNIProxy 项目的简单包装，将配置文件写在了镜像内。配置内容如下：

# 监听端口（注意需要引号）
listen_addr: ":443"

# 可选：启用 Socks5 前置代理
enable_socks5: true
# 可选：配置 Socks5 代理地址
socks_addr: xray:40000

# 可选：允许所有域名（会忽略下面的 rules 列表）
#allow_all_hosts: true

# 可选：仅允许指定域名
rules:
  - openstreetmap.org

这里的 socks_addr 为下方 xray 容器内的 socks 代理监听地址。

这段配置的重点在于，sniproxy 容器配置了 network alias。这个选项的作用是，告诉 docker compose，将指定的域名解析到当前容器。因此，加上了这段配置后，docker 容器内解析 nominatim.openstreetmap.org 这个域名，会自动得到 sniproxy 容器的 docker 网络的 IP，达到将 OpenStreetMap 的 API 请求自动导向 sniproxy，进而导向 xray 代理的目的。

方案二：使用单独的服务器部署 sniproxy

优点：配置简单，无需额外容器
缺点：需要额外的服务器部署 sniproxy，需要占用一个 443 端口

当然，如果有多余的服务器，可以提供一个 443 端口的话，就不用这么麻烦了。直接在服务器上搭建好 sniproxy，然后在 docker-compose.yaml 内的 teslamate 容器配置里增加下面这段就可以了：

extra_hosts:
  nominatim.openstreetmap.org: sniproxy_server_ip

这段配置等同于在 teslamate 的 docker 容器的 /etc/hosts 文件内，写入了域名与 IP 的映射关系，因此所有的 OpenStreetMap 相关的 API 请求，都会被导向 sniproxy 的 IP 地址。

P.S. 其实使用 nginx 的 stream 模块，配合 stream_ssl stream_ssl_preread 两个模块，可以做到不影响现有的网站服务的前提下，与 sniproxy 兼容。但是此方法需要对现有的 nginx 配置进行较大的改动，而我本人的 nginx 配置有十几个文件，实在是不想改，因此就放弃了这种方式。

罗技 Logi MX 系列键盘布局切换方法

2023 年 9 月 13 日2023 年 12 月 9 日 by Orange

本方法适用于所有 MX 系列键盘，非 MX 系列没有尝试，不保证可用。

罗技的 MX 系列键盘通常有两个布局模式，最主要的区别就在于底部的 start 按键和 alt 按键。

通过按键的标记可以看到，start 键（即 Windows 徽标键）在 mac 布局下是 opt 键，而 alt 键在 mac 布局下是 cmd 键。

但是这里的按键布局，翻遍了说明都没有找到如何切换。通过搜索发现，跟键盘第一次连接的设备有关。如果键盘第一次连接 mac，则使用左侧的 mac 布局。如果连接的是 Windows，则使用右侧的 Windows 布局。

这导致对双系统用户极度不友好。切换系统时，会出现按键标记与实际功能不符的情况。于是经过多方搜索，找到了手动切换布局的方法：

切换到 Windows 布局：按住 FN + P 键 3 秒（Hold FN+P for 3 seconds）

切换到 mac 布局：按住 FN + O 键 3 秒（Hold FN+O for 3 seconds）

GoLand 切换代码跳转时的默认系统

2022 年 10 月 21 日2022 年 10 月 21 日 by Orange

由于 go 原生支持了交叉编译，且允许自由的通过编译参数来做到多系统分别编译不同的代码，因此很多项目都实用这种方式来屏蔽跨系统的 API 差异。但是如果我们在非目标系统进行开发，如在 Windows 或 macOS 开发 Linux 程序，就会出现代码跳转的时候无法跳转到正确的文件。

这是因为 GoLand 默认使用我们开发环境的信息来搜索和跳转，因此如果在 Windows 开发，就会跳转到对应的 Windows 的实现。这时候，我们可以通过修改配置，来修改这一跳转行为。具体需要修改的配置为：

Preferences -> Go -> Build Tags & Vendoring

或者使用双击 Shift 输入 Build Tags 来快速定位到这个配置。

在这个配置里，将 OS 和 Arch 修改为目标系统即可。

设置完成后立刻生效，此时再跳转有多系统差异的函数，即可直接跳转到与设置对应的实现。

安全的调试容器内的进程

2022 年 9 月 26 日 by Orange

通常来说，使用 gdb 等工具调试测试或生产环境的进程，是非常好的查找 Bug 的方式。但是当我们步入容器时代后，使用 gdb 工具却会遇到一些麻烦。

当我们进入容器内，尝试使用 gdb attach 的方式开始调试已运行的进程时，会得到这样的报错：

Attaching to process 123
ptrace: Operation not permitted.

通过简单的搜索我们可以发现，这是因为容器内为了安全，默认没有给 SYS_PTRACE 权限的原因。于是，很多教程告诉我们，用这个命令启动容器解决这个问题：

docker run xxx --cap-add=SYS_PTRACE

然而，在生产环境授予容器 SYS_PTRACE 权限是很危险的，有可能造成容器逃逸。因此，如果需要启用该权限，建议慎重考虑。

那么，有没有办法避开这个权限呢？由于容器本身其实就是主机上的一个进程，所以我们自然会想到，能否直接从主机找到对应的进程，然后在主机上执行 gdb attach 呢？

事实上我们可以这样操作，但是由于容器内的二进制文件在主机上并没有，所以 gdb attach 之后会报 No such file，并不能正常工作。就算我们把二进制拷贝出来，放在对应的位置上，gdb 还是会有 warning：

warning: Target and debugger are in different PID namespaces; thread lists and other data are likely unreliable.  Connect to gdbserver inside the container.

这个 warning 就是告诉我们，正在运行的 gdb 进程的 PID namespace 与想要调试的进程的不同，这会导致我们的线程列表等数据出现偏差，可能会影响调试。

考虑到容器的实现原理就是在不同的 namespace 中运行程序，因此如果我们能以容器进程的 namespace 启动一个调试器，那就能解决这个问题了。经过一番搜索，发现 Linux 提供了一个叫 nsenter 的工具来做这件事。我们只需要这样操作：

nsenter -m -u -i -n -p --target ${PID} bash

就可以启动一个跟容器内进程共用同一个 namespace 的 bash，并且该 bash 并没有 SYS_PTRACE 权限的限制，可以非常方便的使用 gdb 了。

深入理解 System.currentTimeMillis() 与时区

2022 年 3 月 18 日2022 年 3 月 18 日 by Orange

今天在解答同事对于 Unix Timestamp 的时区问题的疑问时，看到了这篇文章：

深入理解System.currentTimeMillis()
https://coderdeepwater.cn/2020/12/29/java_source_code/currentTimeMillis/

通过阅读发现，虽然该文章对于这个函数调用的原理解释的非常好，但是却在开头处犯了一个致命的错误，误导了我的同事。在这篇文章中，作者说：

深入理解System.currentTimeMillis()
System.currentTimeMills()的返回值取决于Java运行时系统的本地时区!千万不要忘记这一点!
同一时刻,在英国和中国的两个人同时用System.currentTimeMills()获取当前系统时间,其返回值不是一样的,除非手动将操作系统的时区设置成同一个时区(英国使用UTC+0,而中国使用UTC+8,中国比英国快8个小时).

这个观点是完全错误的，正因为这里的错误误导了我的同事，走入了错误的排查方向。

首先说结论：

System.currentTimeMillis() 的返回值与系统时区无关。在一台时区和时间皆设置正确的机器上，这个函数的返回值总是当前时间与 UTC 0 时的 1970年1月1日 0时0分0秒即 1970-01-01 00:00:00 UTC 的差值
同一时刻，在地球上任意地点的两个人在时区和时间皆设置正确的机器上同时用 System.currentTimeMills() 获取当前系统时间，其返回值一定一样，与时区无关

首先明确几个概念：

时间：是一个客观存在的物理量，是物质运动变化的表现
时间单位：人为了方便对时间进行计量，人为定义了年、月、日、时、分、秒、毫秒等一系列时间单位
公历日期：人为规定的纪年体系，用来记录准确的时间
时区：由于地球自转的存在，地球上各个地区的日升日落时间并不一致。因此为了使用方便，人为将地球划分成了 24 个时区，每两个相邻时区间的时间表示相差 1 小时
Unix 时间戳：人为规定的用来描述一个确切时间点的系统。以 1970-01-01 00:00:00 UTC 为基点，计算当前时间与基点的秒数差，不考虑闰秒

从这几个概念中，我们可以知道，Unix 时间戳是用于精确描述一个确定的时间点，具体的方式是计算两个时间点之间的秒数差。由于我们的宇宙只有单时间线，所以计算两个确定的时间点之间的秒数差，在地球上任何地方的时间都是一致的。因此我们可以知道，在一个确定的时间点上，地球上所有人计算得到的当前的 Unix 时间戳，都应当是一致的。

那么，为什么还有人遇到不同时区获取到的时间戳不一致的问题呢？这就要说到实际使用中对时间的展示方式了。

一个简单的例子，如果我说现在是北京时间 2020年01月01日 08时00分00秒，那么这可以表示一个准确的时刻。对于同一个时刻，我还可以说，现在是格林威治时间 2020年01月01日 00时00分00秒。这两个句子实际上表达的是同一个时刻。

但是，如果我只说现在是 2020年01月01日 00时00分00秒，那么不能表示一个准确的时刻。因为在句话里，我没有说明时区信息，导致缺失了定位到准确时刻的必要条件。

因此我们可以发现，我们日常说话时的表述，其实都是不精确的。那么在程序员的世界里，我们最容易犯的错误，也跟这个类似。

当我们查看一个服务器的时间信息的时候，大多数人不会关心时区信息。假设现在有一台 UTC 0 时区的服务器，很多人拿到后，在检查服务器时间时，第一反应是这个服务器的时间不对，因为桌面上的时钟是 2020年01月01日 08时00分00秒，而机器告诉我的是 2020年1月1日 00时00分00秒，晚了 8 小时。于是，使用 date -s "2020/01/01 08:00:00" 一把梭，再看机器的时间，完美！

那么这时候，如果我用 System.currentTimeMills()来获取时间戳，得到的是什么呢？得到的当然是 1577865600000，代表北京时间 2020年01月01日 16时00分00秒。因为机器本身运行在 0 时区，对于机器来说，现在是 0 时区的 8 点，那换算到 +8 的北京时区，自然是 16 点。

这也就是前面为何一直强调时区和时间皆设置正确的原因。刚说的案例就是典型的时间与时区设置不匹配。机器的时区是 0 时区的，但是用户设置进去的时间却是 +8 时区的。在这种情况下，System.currentTimeMills()自然获取不到正确的值。

因此，我们在修改机器的系统时间时，一定要带上时区信息。如：date -s "2020/01/01 08:00:00 +8" 。这样就可以准确的告诉系统我们想要设置的时刻，避免因为自动的时区转换导致调错机器的时间。

腾讯云云函数 SCF 与轻量服务器互通指南

2022 年 2 月 16 日2022 年 2 月 16 日 by Orange

去年末腾讯云轻量服务器推出了内网互联功能，但是好像有很多小伙伴不太清楚用法。因此写本文给大家一些使用思路。

本文基于官方文档 https://cloud.tencent.com/document/product/1207/56847 。

注意事项

轻量内网互联功能、云联网及 VPC 等功能本身不收费，但若本地互联带宽超过 5Gbps 或需要跨地域互联，则需要收取相关带宽费用。因此本文仅做同地域互联展示
由于轻量的内网 IP 无法自定义，所以建议先购买好需要的轻量服务，再规划内网其他服务（如 SCF、MySQL 等）的网段，以避免内网 IP 冲突
若轻量云 VPC 的 CIDR 与云函数 VPC 的 CIDR 有重合，可能带来一些奇怪的访问不通的问题，建议在网段规划时直接避开重合段
云联网只是打通网络，实际端口访问还是受到防火墙限制。若出现访问不通，请检查轻量服务器的防火墙设置：https://cloud.tencent.com/document/product/1207/44577
已有云函数可以通过编辑函数配置加入 VPC，无需新建
该方法打通网络后，不仅可以做到云函数访问轻量云资源，同样反向访问也是可以的。如允许轻量云服务器访问 VPC 内的其他 CVM 或 MySQL、Kafka、Redis 等资源，但是要注意对应资源的安全组设置，需要放通轻量云服务器的相关网段

操作流程

轻量云内网互联

在对应区域购买轻量云服务，本文以北京区为例

购买完成后进入内网互联页面，可以看到对应区域的关联选项：

点击关联云联网，弹出关联选择页面：

选择需要的云联网。若还未创建云联网，则点击新建。

新建云联网时，由于我们只用本地带宽，因此服务质量直接选择白金即可。若有跨地域互联需求，则按照预算选择对应的服务质量。

下方的关联 VPC 实例可以先不填。直接点击右边的小叉删除即可。

新建完成后，回到关联云联网页面，选择对应的云联网并确认

看到这里说明关联申请已成功提交。接下来需要进入云联网控制台同意关联申请。点击页面中的跳转链接即可快速跳转到对应的云联网控制台

这里要注意，由于轻量服务器是处在腾讯云内部独立账号下，因此这里的所属账号可能与自己的账号不同，这是正常的。如果这里出现了多条记录，我们找对应时间为我们申请关联的时间，备注为 Lighthouse VPC 的申请记录，并点击同意。

接受申请后，状态变为绿色的已连接。

此时回到轻量云的控制台，刷新后会发现已关联成功

到这里，轻量云和云联网的关联已全部完成。此处的内网 CIDR 需要记下，在后续的 VPC 创建中要用。

云函数 SCF 内网互联

接下来我们处理 SCF 与内网资源的互通。

首先我们需要一个 VPC 给 SCF 使用。如果已有规划好的 VPC，则可跳过新建 VPC 步骤。

打开 VPC 控制台，切换到对应的区域。这里使用北京区域。

新建 VPC 时，有两个 CIDR 需要配置。一个是整个大 VPC 的 CIDR 范围，一个是单个子网的 CIDR 范围。还记得之前轻量的 CIDR 么？此处的大 VPC CIDR 可以包含轻量的 CIDR，但是子网的 CIDR 范围最好不要跟轻量的 CIDR 有重叠，否则需要对路由表进行细致的调整，还可能出现 IP 冲突，比较麻烦。

由于我们之前拿到的轻量的 CIDR 是 10.0.24.0/22，因此这里我们给子网分配 10.0.0.0/24，避免冲突。

接下来我们需要将这个 VPC 关联到刚才的云联网中。

回到云联网的控制台，在关联实例页面，选择新增实例

依次选择私有网络-对应地域-对应 VPC，并确认。

确认后即可看到我们刚刚新建的 VPC 和轻量的 VPC 均为已连接状态。

为了确保没有 CIDR 冲突，我们需要确认一下路由表状态。点击上方的路由表页面进行确认

看到两条路由表均为有效且启用的状态，说明互联已完成。

若此处出现路由冲突，请参考官方文档解决。

云函数使用 VPC 网络

现在一切准备就绪，我们可以使用 SCF 访问轻量服务器了。

为了测试方便，我在轻量服务器上启动了一个 nginx 服务，并开启了对应的防火墙。这里的操作与互联无关，因此不再赘述。

现在来到云函数的控制台，在对应地域新建云函数。这里选择北京，使用 python 语言。

函数代码使用 python 写了一个简单的获取网页内容并输出：

# -*- coding: utf8 -*-
import json
import urllib.request
def main_handler(event, context):
    resp = urllib.request.urlopen("http://10.0.24.x") # 这里是轻量服务器的内网 IP
    print(resp.read())

在填写完函数内容后，展开下方的高级设置：

我们需要关注的是这里的私有网络，其他设置按需调整即可，与互联无关。

我们勾选启用私有网络：

待加载完成后，选择我们之前创建好并关联了云联网的私有网络，然后点击页面最下方的完成即可。

待函数部署成功后，查看函数配置，看到对应的 VPC 配置，即为配置成功。

接下来测试一下函数是否可以跑通，进入函数代码页面，点击编辑器下方的测试：

测试完成后，会在下方输出测试结果：

可以看到，云函数成功通过内网拉到了位于轻量云服务器上的 nginx 服务的数据。

Linux 下查看指定进程环境变量信息

2021 年 12 月 15 日 by Orange

Linux 会为每个进程生成一个目录，保存了进程相关的大量信息。具体位置在：

/proc/${pid}

一般有如下文件：

total 0
-rw-r--r-- 1 root root 0 Dec 31 00:00 autogroup
-r-------- 1 root root 0 Dec 31 00:00 auxv
-r--r--r-- 1 root root 0 Dec 31 00:00 cgroup
--w------- 1 root root 0 Dec 31 00:00 clear_refs
-r--r--r-- 1 root root 0 Dec 31 00:00 cmdline
-rw-r--r-- 1 root root 0 Dec 31 00:00 comm
-rw-r--r-- 1 root root 0 Dec 31 00:00 coredump_filter
-r--r--r-- 1 root root 0 Dec 31 00:00 cpuset
lrwxrwxrwx 1 root root 0 Dec 31 00:00 cwd -> /root
-r-------- 1 root root 0 Dec 31 00:00 environ
lrwxrwxrwx 1 root root 0 Dec 31 00:00 exe -> /usr/bin/bash
dr-x------ 2 root root 0 Dec 31 00:00 fd
dr-x------ 2 root root 0 Dec 31 00:00 fdinfo
-r--r--r-- 1 root root 0 Dec 31 00:00 hostinfo
-r-------- 1 root root 0 Dec 31 00:00 io
-r--r--r-- 1 root root 0 Dec 31 00:00 latency
-r--r--r-- 1 root root 0 Dec 31 00:00 limits
-rw-r--r-- 1 root root 0 Dec 31 00:00 loginuid
-r--r--r-- 1 root root 0 Dec 31 00:00 maps
-rw------- 1 root root 0 Dec 31 00:00 mem
-r--r--r-- 1 root root 0 Dec 31 00:00 mountinfo
-r--r--r-- 1 root root 0 Dec 31 00:00 mounts
-r-------- 1 root root 0 Dec 31 00:00 mountstats
dr-xr-xr-x 7 root root 0 Dec 31 00:00 net
dr-x--x--x 2 root root 0 Dec 31 00:00 ns
-r--r--r-- 1 root root 0 Dec 31 00:00 numa_maps
-rw-r--r-- 1 root root 0 Dec 31 00:00 oom_adj
-r--r--r-- 1 root root 0 Dec 31 00:00 oom_score
-rw-r--r-- 1 root root 0 Dec 31 00:00 oom_score_adj
-r--r--r-- 1 root root 0 Dec 31 00:00 pagemap
-r--r--r-- 1 root root 0 Dec 31 00:00 personality
lrwxrwxrwx 1 root root 0 Dec 31 00:00 root -> /
-rw-r--r-- 1 root root 0 Dec 31 00:00 sched
-r--r--r-- 1 root root 0 Dec 31 00:00 sessionid
-r--r--r-- 1 root root 0 Dec 31 00:00 smaps
-r--r--r-- 1 root root 0 Dec 31 00:00 stack
-r--r--r-- 1 root root 0 Dec 31 00:00 stat
-r--r--r-- 1 root root 0 Dec 31 00:00 statm
-r--r--r-- 1 root root 0 Dec 31 00:00 status
-r--r--r-- 1 root root 0 Dec 31 00:00 syscall
dr-xr-xr-x 3 root root 0 Dec 31 00:00 task
-r--r--r-- 1 root root 0 Dec 31 00:00 wchan

其中的 exe 指向进程的可执行文件，cwd 指向进程的工作目录，environ 就是进程所看到的环境变量的信息了。

直接 cat 这个文件，可以看到所有的变量信息。但是这里看到的变量都是挤在一起的，没有换行。

使用 vim 打开这个文件，可以看到实际上文件中是有符号分隔的，在 vim 里展示为 ^@ 。经过搜索，该符号代表的其实是 \0，也就是字符串结尾的意思。于是使用 tr 命令稍作处理，即可得到可读性强的换行分隔的环境变量信息：

tr '\0' '\n'< /proc/${pid}/environ

使用 Quartz 调度器遇到的一些问题

2021 年 4 月 17 日2021 年 4 月 23 日 by Orange

最近，线上运行的定时任务出现调度失败。调整了相关参数后，虽然遏制了调度失败的情况，却导致任务调度的延迟极度增加。同时还观察到，在多机部署的环境中，负载极不均匀，于是深入代码排查一番。

TL; DR

不要使用 Spring 提供的 org.springframework.scheduling.quartz.SchedulerFactoryBean#setTaskExecutor 方法自定义工作线程池
要注意 Spring 与 Quartz 的部分配置默认值不一致，如 org.quartz.threadPool.class
一般情况下使用 Quartz 提供的 SimpleThreadPool 配合参数 org.quartz.threadPool.threadCount 调整最大线程数即可
如果需要自定义工作线程池，则必须直接实现 org.quartz.spi.ThreadPool 接口，并一定要实现 blockForAvailableThreads 方法，支持阻塞等待
适当设置 org.quartz.scheduler.batchTriggerAcquisitionMaxCount 参数，使用批量能力降低 DB 交互带来的延迟

任务调度失败

问题现象

接用户反馈，一个一直正常运行的定时任务，在确认没有进行任何变动的情况下，却突然不再被调度了。经过确认，确实没有找到该任务的任何改动痕迹。因此怀疑问题是出在 Quartz 调度引擎上。

找出原因

看到这个现象，第一反应是 Quartz 里的 Trigger 异常了。因为 Quartz 对于所有状态是异常的 Trigger 都不会再次调度，表现为没有任何操作但是任务不执行。于是查看 QRTZ_TRIGGERS 表，筛选过后果然看到了 STATE 为 ERROR 的 TRIGGER。根据 TRIGGER_NAME 和 TRIGGER_GROUP 确定为用户反馈的任务所对应的触发器。

确定了问题是 TRIGGER_STATE 后，就要找到状态变化的点。先查看出现问题时的业务日志，可以看到有这样的记录穿插其中：

[2021-04-16 16:14:08.001][|][quartz-scheduler_QuartzSchedulerThread] ERROR o.s.s.q.LocalTaskExecutorThreadPool:runInThread:84 - Task has been rejected by TaskExecutor
 org.springframework.core.task.TaskRejectedException: Executor [java.util.concurrent.ThreadPoolExecutor@ef3310e[Running, pool size = 50, active threads = 50, queued tasks = 100, completed tasks = 20]] did not accept task: org.quartz.core.JobRunShell@5841bfb6
         at org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor.execute(ThreadPoolTaskExecutor.java:324)
         at org.springframework.scheduling.quartz.LocalTaskExecutorThreadPool.runInThread(LocalTaskExecutorThreadPool.java:80)
         at org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:398)
 Caused by: java.util.concurrent.RejectedExecutionException: Task org.quartz.core.JobRunShell@5841bfb6 rejected from java.util.concurrent.ThreadPoolExecutor@ef3310e[Running, pool size = 50, active threads = 50, queued tasks = 100, completed tasks = 20]
         at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2063)
         at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830)
         at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1379)
         at org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor.execute(ThreadPoolTaskExecutor.java:321)
         … 2 common frames omitted
 [2021-04-16 16:14:08.001][|][quartz-scheduler_QuartzSchedulerThread] ERROR o.quartz.core.QuartzSchedulerThread:run:403 - ThreadPool.runInThread() return false!

从日志里可以看到，有一些定时任务被线程池拒绝了。而我们的线程池中有 50 个工作线程，100 个等待队列。也就是说这台机器短时间内承担了 150 个以上的调度任务，就会导致线程池无法承受如此多的任务而导致后续的任务被拒绝执行。因此猜测这部分被拒绝执行的任务导致了 Quartz 的 Trigger 状态异常。

于是查找相关代码，可以看到有一共有四处修改状态为 ERROR 的代码。其中由于 retrieveJob 导致的错误暂时排除，因为 DB 中 Trigger 的数据都是高度相似的。如果是这里出了问题，那么一定是大批量的出现错误，而非个别任务。继续查找，找到如下逻辑：

JobRunShell shell = null;
try {
    // 创建触发器执行环境
    shell = qsRsrcs.getJobRunShellFactory().createJobRunShell(bndle);
    shell.initialize(qs);
} catch (SchedulerException se) {
    qsRsrcs.getJobStore().triggeredJobComplete(triggers.get(i), bndle.getJobDetail(), Trigger.CompletedExecutionInstruction.SET_ALL_JOB_TRIGGERS_ERROR);
    continue;
}

// 提交执行并检查提交结果
if (qsRsrcs.getThreadPool().runInThread(shell) == false) {
    // this case should never happen, as it is indicative of the
    // scheduler being shutdown or a bug in the thread pool or
    // a thread pool being used concurrently - which the docs
    // say not to do...
    getLog().error("ThreadPool.runInThread() return false!");
    qsRsrcs.getJobStore().triggeredJobComplete(triggers.get(i), bndle.getJobDetail(), Trigger.CompletedExecutionInstruction.SET_ALL_JOB_TRIGGERS_ERROR);
}

从这里可以看到，如果任务提交到线程池的时候失败了，那么就会导致任务被标记为 ERROR。而这刚好符合我们看到的日志现象。由于线程池等待队列满导致的提交异常这种情况只会在等待队列撑满之后才会发生，刚好符合大部分任务没有问题但少部分任务失败的情况，于是确定了问题的原因。

深入分析

虽然找到了调度失败的原因是由于线程池满引起的，但是经过计算，这并不是设计中应该出现的。因为在设计中，业务一共有三台机器分别调度任务，而总任务数量在 300～400 左右。期望中每台机器都应承载 1/3 左右的业务量，也就是约 100～140 个任务左右。在这种情况下，理论上每台机器的线程池都应刚好能满足业务需要的，不应该出现这种情况。而通过查看日志，会发现实际上大部分任务都由一台机器执行，另外两台只分配到了少量任务。这种倾斜直接导致了任务量最大的机器数量爆表，导致线程池处理不及时，进而导致任务提交失败，被 Quartz 标记为异常，停止调度。

误入歧途

既然找到了问题在于 Quartz 调度任务的速度太快，线程池来不及处理，于是想到通过参数配置降低 Quartz 调度线程投递任务的速度，并尝试调升队列缓冲来解决这个问题。通过阅读调度器的代码，找到如下逻辑：

@Override
public void run() {
    int acquiresFailed = 0;

    while (!halted.get()) {
        try {
            // do some process states check

            int availThreadCount = qsRsrcs.getThreadPool().blockForAvailableThreads();
            if(availThreadCount > 0) { // will always be true, due to semantics of blockForAvailableThreads...

                List<OperableTrigger> triggers;

                long now = System.currentTimeMillis();

                clearSignaledSchedulingChange();
                try {
                    triggers = qsRsrcs.getJobStore().acquireNextTriggers(
                            now + idleWaitTime, Math.min(availThreadCount, qsRsrcs.getMaxBatchSize()), qsRsrcs.getBatchTimeWindow());
                    acquiresFailed = 0;
                    if (log.isDebugEnabled())
                        log.debug("batch acquisition of " + (triggers == null ? 0 : triggers.size()) + " triggers");
                } catch (JobPersistenceException jpe) {
                    // do exception process
                    continue;
                } catch (RuntimeException e) {
                    // do exception process 
                    continue;
                }

                if (triggers != null && !triggers.isEmpty()) {

                    now = System.currentTimeMillis();
                    long triggerTime = triggers.get(0).getNextFireTime().getTime();
                    long timeUntilTrigger = triggerTime - now;
                    while(timeUntilTrigger > 2) {
                        synchronized (sigLock) {
                            if (halted.get()) {
                                break;
                            }
                            if (!isCandidateNewTimeEarlierWithinReason(triggerTime, false)) {
                                try {
                                    // we could have blocked a long while
                                    // on 'synchronize', so we must recompute
                                    now = System.currentTimeMillis();
                                    timeUntilTrigger = triggerTime - now;
                                    if(timeUntilTrigger >= 1)
                                        sigLock.wait(timeUntilTrigger);
                                } catch (InterruptedException ignore) {
                                }
                            }
                        }
                        if(releaseIfScheduleChangedSignificantly(triggers, triggerTime)) {
                            break;
                        }
                        now = System.currentTimeMillis();
                        timeUntilTrigger = triggerTime - now;
                    }

                    // do some check

                    if(goAhead) {
                        try {
                            List<TriggerFiredResult> res = qsRsrcs.getJobStore().triggersFired(triggers);
                            if(res != null)
                                bndles = res;
                        } catch (SchedulerException se) {
                            // do exception process
                            continue;
                        }

                    }

                    for (int i = 0; i < bndles.size(); i++) {
                        TriggerFiredResult result =  bndles.get(i);
                        TriggerFiredBundle bndle =  result.getTriggerFiredBundle();
                        Exception exception = result.getException();

                        // do some check

                        JobRunShell shell = null;
                        try {
                            shell = qsRsrcs.getJobRunShellFactory().createJobRunShell(bndle);
                            shell.initialize(qs);
                        } catch (SchedulerException se) {
                            qsRsrcs.getJobStore().triggeredJobComplete(triggers.get(i), bndle.getJobDetail(), CompletedExecutionInstruction.SET_ALL_JOB_TRIGGERS_ERROR);
                            continue;
                        }

                        if (qsRsrcs.getThreadPool().runInThread(shell) == false) {
                            // this case should never happen, as it is indicative of the
                            // scheduler being shutdown or a bug in the thread pool or
                            // a thread pool being used concurrently - which the docs
                            // say not to do...
                            getLog().error("ThreadPool.runInThread() return false!");
                            qsRsrcs.getJobStore().triggeredJobComplete(triggers.get(i), bndle.getJobDetail(), CompletedExecutionInstruction.SET_ALL_JOB_TRIGGERS_ERROR);
                        }

                    }

                    continue; // while (!halted)
                }
            } else { // if(availThreadCount > 0)
                // should never happen, if threadPool.blockForAvailableThreads() follows contract
                continue; // while (!halted)
            }

            long now = System.currentTimeMillis();
            long waitTime = now + getRandomizedIdleWaitTime();
            long timeUntilContinue = waitTime - now;
            synchronized(sigLock) {
                try {
                    if(!halted.get()) {
                        // QTZ-336 A job might have been completed in the mean time and we might have
                        // missed the scheduled changed signal by not waiting for the notify() yet
                        // Check that before waiting for too long in case this very job needs to be
                        // scheduled very soon
                        if (!isScheduleChanged()) {
                            sigLock.wait(timeUntilContinue);
                        }
                    }
                } catch (InterruptedException ignore) {
                }
            }

        } catch(RuntimeException re) {
            getLog().error("Runtime error occurred in main trigger firing loop.", re);
        }
    } // while (!halted)

    // drop references to scheduler stuff to aid garbage collection...
    qs = null;
    qsRsrcs = null;
}

这段是 Quartz 调度线程的主要逻辑，注意其中的这段：

triggers = qsRsrcs.getJobStore().acquireNextTriggers(
                            now + idleWaitTime, Math.min(availThreadCount, qsRsrcs.getMaxBatchSize()), qsRsrcs.getBatchTimeWindow());

这里可以看到，Quartz 每次从 DB 拉取的任务数量与线程池的可用线程数和一个参数 MaxBatchSize 有关。根据查阅到的一些文章，说此处 Quartz 会每次拉取线程数个任务。因此怀疑这里是由于工作线程池的线程数量过大，导致任务都被一台机器拉取，导致的负载不均衡。于是尝试调小线程池的参数，来缓解拉取任务过多的问题。这里要说下，这个怀疑是错误的！让我误入歧途。具体原因会在后面说明。

问题“解决“

通过调整此处线程池的参数，任务执行出错的问题再也没有出现。本以为所有的问题就这样解决了，没想到却引来了另一个更棘手的问题：调度延迟。

任务调度延迟

问题现象

接用户反馈，部分每分钟执行一次的定时任务，出现了同一分钟内执行两次的情况。在任务的执行历史里可以明显看到 12:01:09 有一次执行，12:01:22 的时候又出现了一次执行。

找出原因

由于 Quartz 调度器本身是不太容易犯重复调度这样的错误的，因此第一时间考虑是任务调度延迟导致的。通过观察用户的定时任务，发现实际上该任务在 11:59:02 12:01:09 和 12:01:22 分别调度一次。因此可以确定，12:01 的两次调度，一次为正常的调度，一次为 12:00 应当调度的任务但是因为某些原因延迟了。这样才导致整个调度看起来就像是在 12:01 的之后重复调度了一次。

那么现在的问题就在于调度延迟了。由于之前比较激进的调整过线程池的参数，因此这里还是主要考虑在线程池周边找问题。通过调大线程池的参数，可以明显的发现总体调度延迟飞速降低。但是在测试的过程中，还是在日志里发现了一点之前忽略的小问题：

[2021-04-16 20:27:00.051][|][threadPoolTaskExecutor-1] Execute task|1|1
[2021-04-16 20:27:00.100][|][threadPoolTaskExecutor-2] Execute task|1|2
[2021-04-16 20:27:00.157][|][threadPoolTaskExecutor-3] Execute task|1|3
[2021-04-16 20:27:00.213][|][threadPoolTaskExecutor-4] Execute task|1|4
[2021-04-16 20:27:00.268][|][threadPoolTaskExecutor-5] Execute task|1|5
[2021-04-16 20:27:00.323][|][threadPoolTaskExecutor-6] Execute task|1|6
[2021-04-16 20:27:00.379][|][threadPoolTaskExecutor-7] Execute task|1|7
[2021-04-16 20:27:00.437][|][threadPoolTaskExecutor-8] Execute task|1|8
[2021-04-16 20:27:00.492][|][threadPoolTaskExecutor-9] Execute task|1|9
[2021-04-16 20:27:00.554][|][threadPoolTaskExecutor-10] Execute task|1|10
[2021-04-16 20:27:00.610][|][threadPoolTaskExecutor-11] Execute task|1|11
[2021-04-16 20:27:00.667][|][threadPoolTaskExecutor-12] Execute task|1|12
[2021-04-16 20:27:00.721][|][threadPoolTaskExecutor-13] Execute task|1|13
[2021-04-16 20:27:00.775][|][threadPoolTaskExecutor-14] Execute task|1|14
[2021-04-16 20:27:00.831][|][threadPoolTaskExecutor-15] Execute task|1|15
[2021-04-16 20:27:00.885][|][threadPoolTaskExecutor-16] Execute task|1|16
[2021-04-16 20:27:00.937][|][threadPoolTaskExecutor-17] Execute task|1|17
[2021-04-16 20:27:00.991][|][threadPoolTaskExecutor-18] Execute task|1|18
[2021-04-16 20:27:01.044][|][threadPoolTaskExecutor-19] Execute task|1|19
[2021-04-16 20:27:01.098][|][threadPoolTaskExecutor-20] Execute task|1|20
[2021-04-16 20:27:01.152][|][threadPoolTaskExecutor-21] Execute task|1|21
[2021-04-16 20:27:01.206][|][threadPoolTaskExecutor-22] Execute task|1|22
[2021-04-16 20:27:01.261][|][threadPoolTaskExecutor-23] Execute task|1|23
[2021-04-16 20:27:01.315][|][threadPoolTaskExecutor-24] Execute task|1|24
[2021-04-16 20:27:01.372][|][threadPoolTaskExecutor-25] Execute task|1|25
[2021-04-16 20:27:01.427][|][threadPoolTaskExecutor-26] Execute task|1|26
[2021-04-16 20:27:01.481][|][threadPoolTaskExecutor-27] Execute task|1|27
[2021-04-16 20:27:01.536][|][threadPoolTaskExecutor-28] Execute task|1|28
[2021-04-16 20:27:01.590][|][threadPoolTaskExecutor-29] Execute task|1|29
[2021-04-16 20:27:01.644][|][threadPoolTaskExecutor-30] Execute task|1|30
[2021-04-16 20:27:01.698][|][threadPoolTaskExecutor-31] Execute task|1|31
[2021-04-16 20:27:01.757][|][threadPoolTaskExecutor-32] Execute task|1|32
[2021-04-16 20:27:01.811][|][threadPoolTaskExecutor-33] Execute task|1|33
[2021-04-16 20:27:01.866][|][threadPoolTaskExecutor-34] Execute task|1|34
[2021-04-16 20:27:01.920][|][threadPoolTaskExecutor-35] Execute task|1|35
[2021-04-16 20:27:01.973][|][threadPoolTaskExecutor-36] Execute task|1|36
[2021-04-16 20:27:02.031][|][threadPoolTaskExecutor-37] Execute task|1|37
[2021-04-16 20:27:02.086][|][threadPoolTaskExecutor-38] Execute task|1|38
[2021-04-16 20:27:02.139][|][threadPoolTaskExecutor-39] Execute task|1|39
[2021-04-16 20:27:02.194][|][threadPoolTaskExecutor-40] Execute task|1|40
[2021-04-16 20:27:02.247][|][threadPoolTaskExecutor-41] Execute task|1|41
[2021-04-16 20:27:02.301][|][threadPoolTaskExecutor-42] Execute task|1|42
[2021-04-16 20:27:02.354][|][threadPoolTaskExecutor-43] Execute task|1|43
[2021-04-16 20:27:02.407][|][threadPoolTaskExecutor-44] Execute task|1|44
[2021-04-16 20:27:02.460][|][threadPoolTaskExecutor-45] Execute task|1|45
[2021-04-16 20:27:02.513][|][threadPoolTaskExecutor-46] Execute task|1|46
[2021-04-16 20:27:02.567][|][threadPoolTaskExecutor-47] Execute task|1|47
[2021-04-16 20:27:02.620][|][threadPoolTaskExecutor-48] Execute task|1|48
[2021-04-16 20:27:02.680][|][threadPoolTaskExecutor-49] Execute task|1|49
[2021-04-16 20:27:02.734][|][threadPoolTaskExecutor-50] Execute task|1|50

可以看到，日志里每两个任务的启动时间，都间隔了 50ms 左右。这个时间并不在预期中。按照设想，Quartz 应该一次性拿可用线程数个任务，然后批量提交才对。如果是批量提交到线程池，正常情况下不应有这么大的启动延迟。就算是因为 CPU 调度的原因，在这台 4C 的机器上，前四个任务的启动时间也不应有特别巨大的偏差才对。而且这台测试机为了避免干扰，除了必要的 SSH 等服务外，没有运行任何其他服务，也不存在 CPU 或内存争抢的情况。

为了确认猜想，使用相同的参数创建了相同的线程池，并使用循环批量提交任务，来测试线程池内线程的启动延迟：

ThreadPoolTaskExecutor threadPoolTaskExecutor = new ThreadPoolTaskExecutor();
threadPoolTaskExecutor.setCorePoolSize(150);
threadPoolTaskExecutor.setMaxPoolSize(300);
threadPoolTaskExecutor.setQueueCapacity(150);
threadPoolTaskExecutor.initialize();

int count = 0;
while (count < 200) {
    threadPoolTaskExecutor.execute(() -> {
        log.info("Execute start at {}", System.currentTimeMillis());
        try {
            Thread.sleep(2_000);
        } catch (InterruptedException e) {
            log.error("Interrupted exception while execute task!", e);
            Thread.interrupted();
        }
        log.info("Execute end at {}", System.currentTimeMillis());
    });

    count++;
}

经过测试，得到的日志输出是这样的：

[2021-04-17 11:29:06.360][|][ThreadPoolTaskExecutor-1] Execute start
[2021-04-17 11:29:06.361][|][ThreadPoolTaskExecutor-2] Execute start
[2021-04-17 11:29:06.371][|][ThreadPoolTaskExecutor-6] Execute start
[2021-04-17 11:29:06.371][|][ThreadPoolTaskExecutor-5] Execute start
[2021-04-17 11:29:06.372][|][ThreadPoolTaskExecutor-7] Execute start
[2021-04-17 11:29:06.369][|][ThreadPoolTaskExecutor-4] Execute start
[2021-04-17 11:29:06.362][|][ThreadPoolTaskExecutor-3] Execute start
[2021-04-17 11:29:06.374][|][ThreadPoolTaskExecutor-8] Execute start
[2021-04-17 11:29:06.375][|][ThreadPoolTaskExecutor-9] Execute start
[2021-04-17 11:29:06.382][|][ThreadPoolTaskExecutor-11] Execute start
[2021-04-17 11:29:06.382][|][ThreadPoolTaskExecutor-10] Execute start
[2021-04-17 11:29:06.382][|][ThreadPoolTaskExecutor-12] Execute start
[2021-04-17 11:29:06.384][|][ThreadPoolTaskExecutor-13] Execute start
[2021-04-17 11:29:06.384][|][ThreadPoolTaskExecutor-14] Execute start
[2021-04-17 11:29:06.385][|][ThreadPoolTaskExecutor-15] Execute start
[2021-04-17 11:29:06.385][|][ThreadPoolTaskExecutor-16] Execute start
[2021-04-17 11:29:06.386][|][ThreadPoolTaskExecutor-18] Execute start
[2021-04-17 11:29:06.386][|][ThreadPoolTaskExecutor-17] Execute start
[2021-04-17 11:29:06.392][|][ThreadPoolTaskExecutor-19] Execute start
[2021-04-17 11:29:06.393][|][ThreadPoolTaskExecutor-20] Execute start
[2021-04-17 11:29:06.393][|][ThreadPoolTaskExecutor-21] Execute start
[2021-04-17 11:29:06.394][|][ThreadPoolTaskExecutor-22] Execute start
[2021-04-17 11:29:06.394][|][ThreadPoolTaskExecutor-23] Execute start
[2021-04-17 11:29:06.395][|][ThreadPoolTaskExecutor-24] Execute start
[2021-04-17 11:29:06.395][|][ThreadPoolTaskExecutor-25] Execute start
[2021-04-17 11:29:06.396][|][ThreadPoolTaskExecutor-26] Execute start
[2021-04-17 11:29:06.396][|][ThreadPoolTaskExecutor-27] Execute start
[2021-04-17 11:29:06.397][|][ThreadPoolTaskExecutor-28] Execute start
[2021-04-17 11:29:06.397][|][ThreadPoolTaskExecutor-29] Execute start
[2021-04-17 11:29:06.398][|][ThreadPoolTaskExecutor-30] Execute start
[2021-04-17 11:29:06.398][|][ThreadPoolTaskExecutor-31] Execute start
[2021-04-17 11:29:06.399][|][ThreadPoolTaskExecutor-32] Execute start
[2021-04-17 11:29:06.400][|][ThreadPoolTaskExecutor-33] Execute start
[2021-04-17 11:29:06.400][|][ThreadPoolTaskExecutor-34] Execute start
[2021-04-17 11:29:06.400][|][ThreadPoolTaskExecutor-35] Execute start
[2021-04-17 11:29:06.401][|][ThreadPoolTaskExecutor-36] Execute start
[2021-04-17 11:29:06.402][|][ThreadPoolTaskExecutor-37] Execute start
[2021-04-17 11:29:06.402][|][ThreadPoolTaskExecutor-38] Execute start
[2021-04-17 11:29:06.402][|][ThreadPoolTaskExecutor-39] Execute start
[2021-04-17 11:29:06.403][|][ThreadPoolTaskExecutor-40] Execute start
[2021-04-17 11:29:06.410][|][ThreadPoolTaskExecutor-42] Execute start
[2021-04-17 11:29:06.411][|][ThreadPoolTaskExecutor-41] Execute start
[2021-04-17 11:29:06.411][|][ThreadPoolTaskExecutor-43] Execute start
[2021-04-17 11:29:06.412][|][ThreadPoolTaskExecutor-44] Execute start
[2021-04-17 11:29:06.412][|][ThreadPoolTaskExecutor-45] Execute start
[2021-04-17 11:29:06.413][|][ThreadPoolTaskExecutor-46] Execute start
[2021-04-17 11:29:06.421][|][ThreadPoolTaskExecutor-47] Execute start
[2021-04-17 11:29:06.422][|][ThreadPoolTaskExecutor-48] Execute start
[2021-04-17 11:29:06.424][|][ThreadPoolTaskExecutor-49] Execute start
[2021-04-17 11:29:06.424][|][ThreadPoolTaskExecutor-50] Execute start

可以看到，在相同的一台四核的机器上，除了最开始启动较慢外，余下的任务启动时间的偏差基本在 1ms 内。50 个任务全部启动也只用了 60ms 左右。前 150 个任务的启动时间总过也就相差 200ms 左右。这个结果表明，定时任务调度时一定还有其他耗时操作穿插其间，导致任务的提交本身存在延迟，才导致了前 50 个任务的启动时间偏差接近 3s。

深入分析

于是回到代码本身，深入分析 Quartz 的任务调度和提交逻辑。参考前面提供的 QuartzSchedulerThread 主调度线程的代码，我们可以把整个调度过程进行一个阶段划分：

等待工作线程池出现可用线程
根据可用线程数和最大批量大小从 DB 中取出将要触发的 Trigger
循环等待，直到离最近一个要出发的 Trigger 的触发时间还有 2ms
更新 DB 设置当前批次 Trigger 的触发状态
提交 Trigger 到执行线程池

其中 2 4 两步需要访问 DB 更新 Trigger 的状态，并且需要获取 TRIGGER_ACCESS 锁。按照访问 DB 的一般耗时估算，一次 DB 操作大约会消耗 5～10ms 的时间，那么这两步的 DB 操作大约每次会消耗 15～20ms 左右的时间，刚好与我们之前观察到的 50ms 的延迟接近。

可是按照正常逻辑，此处 Quartz 应该是批量去取 Trigger，应该每一批 Trigger 消耗 50ms 才是正常现象。现在每一个 Trigger 都间隔了 50ms，说明此处的批量处理一定出现了问题。于是单独深入批量拉取 Trigger 这段代码，发现之前被忽略的 maxBatchSize 有问题。由于理所当然的认为该选项的值一定会比较大，不太可能成为瓶颈，之前就没有仔细追踪这个参数。现在经过追溯，发现该值在 org.quartz.core.QuartzSchedulerResources 中存在一个默认值 1。也就是说如果没有特殊配置的话，这里的批量永远是单个拉取。这也说明了，之前的猜测是完全错误的。负载不均匀导致队列爆掉并不是因为 Quartz 批量过大导致的，而是另有原因。

尝试修复

既然找到了这个变量漏设置了值，那就修改这里的默认值，再进行测试。这里这个变量值需要修改 Quartz 的配置文件，增加 org.quartz.scheduler.batchTriggerAcquisitionMaxCount 配置项。这里修改成 50 进行测试，配合线程池的 core size 150，应该可以达到每批次处理 50 个 Trigger 的目的。修改后的日志如下：

[2021-04-17 13:45:00.051][|][threadPoolTaskExecutor-1] Execute task|1|1
[2021-04-17 13:45:00.108][|][threadPoolTaskExecutor-2] Execute task|1|2
[2021-04-17 13:45:00.173][|][threadPoolTaskExecutor-3] Execute task|1|3
[2021-04-17 13:45:00.231][|][threadPoolTaskExecutor-4] Execute task|1|4
[2021-04-17 13:45:00.288][|][threadPoolTaskExecutor-5] Execute task|1|5
[2021-04-17 13:45:00.346][|][threadPoolTaskExecutor-6] Execute task|1|6
[2021-04-17 13:45:00.403][|][threadPoolTaskExecutor-7] Execute task|1|7
[2021-04-17 13:45:00.462][|][threadPoolTaskExecutor-8] Execute task|1|8
[2021-04-17 13:45:00.518][|][threadPoolTaskExecutor-9] Execute task|1|9
[2021-04-17 13:45:00.574][|][threadPoolTaskExecutor-10] Execute task|1|10
[2021-04-17 13:45:00.629][|][threadPoolTaskExecutor-11] Execute task|1|11
[2021-04-17 13:45:00.687][|][threadPoolTaskExecutor-12] Execute task|1|12
[2021-04-17 13:45:00.741][|][threadPoolTaskExecutor-13] Execute task|1|13
[2021-04-17 13:45:00.795][|][threadPoolTaskExecutor-14] Execute task|1|14
[2021-04-17 13:45:00.849][|][threadPoolTaskExecutor-15] Execute task|1|15
[2021-04-17 13:45:00.915][|][threadPoolTaskExecutor-16] Execute task|1|16
[2021-04-17 13:45:00.971][|][threadPoolTaskExecutor-17] Execute task|1|17
[2021-04-17 13:45:01.026][|][threadPoolTaskExecutor-18] Execute task|1|18
[2021-04-17 13:45:01.081][|][threadPoolTaskExecutor-19] Execute task|1|19
[2021-04-17 13:45:01.135][|][threadPoolTaskExecutor-20] Execute task|1|20

奇怪的事情发生了，这个参数的修改完全没有起作用，Quartz 还是一个个任务调度的，而不是批量调度。同时在为了测试专门开启的调度引擎的 Debug 日志中也发现了相关日志：

[2021-04-17 13:45:00.076][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.135][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.201][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.258][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.315][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.373][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.431][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.488][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.545][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers
[2021-04-17 13:45:00.600][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 1 triggers

从这里可以看出，调度器确实每次只取了一个 Trigger 进行触发。这就很奇怪了，明明我们已经修改了最大批量值的参数，却看起来像没有生效。考虑到这里的批量值是由两个参数决定的，那么问题一定出在二者之间

线程池可用线程数有问题，获取到的数据不是设置的 150 个线程
maxBatchSize 参数设置没有生效，仍然为 1

由于这两个参数在调度器之外比较用非入侵的方式检测，于是决定直接上 IDEA 用远程调试来解决：

在调度线程批量拉取 Trigger 的地方设置断点，通过查看两个变量的值，发现了问题。这里可以清晰的看到 maxBatchSize 已经变为我们设置的 50 了。但是 availThreadCount 却不是预想中的 150，而是 1。于是检查一下这个线程池：

可以看到，此处用来接收任务的线程池居然是 LocalTaskExecutorThreadPool 类型的线程池，而不是我们在配置里提供给 Quartz 的。而在初始化时提供给 Quartz 的线程池变成了该线程池内部的一个 executor。那这个线程池是哪来的呢？跟进去看下：

可以看到这个线程池是 spring 对于我们实际使用的线程池的一个封装。这个线程池内部的 taskExecutor 才是真正的由我们配置的执行任务的线程池。而这个封装中，由于内部的 executor 是不确定的，所以为了简单，此处的可用线程数查询居然永久返回 1。至此问题的根源找到了：因为 LocalTaskExecutorThreadPool 封装了我们提供给 Quartz 的线程池，且该封装在获取可用线程数时永远返回 1，导致了我们修改 maxBatchSize 没有生效。

再次深入

那么这里其实还有个问题，就是这个 LocalTaskExecutorThreadPool 是从何而来，为何没有直接使用我们构造好的 ThreadPoolTaskExecutor 呢？

经过追踪，发现这个线程池的来源在这里：

org.springframework.scheduling.quartz.SchedulerFactoryBean

可以看到，这是 Spring 对于 Quartz 初始化的一个封装。在这个封装中，如果 Spring 发现我们尝试使用自己配置的一个任务执行器的话，就会默认用 LocalTaskExecutorThreadPool 来做一个包装，除非在配置文件中配置 org.quartz.threadPool.class 显示的覆盖这个参数。而通过阅读配置，我发现这里确实是没有设置值。通过参考 Quartz 本身的初始化过程，猜测当时没有设置这个值的原因是因为 Quartz 本身默认会使用 SimpleThreadPool 来运行任务，因此考虑这个设置是多余的，于是没有进行设置。但是在考虑的过程中却忽略了 Spring 这块，导致实际的效果与预期不一致。

真相大白

至此，这里无法进行批量调度导致调度延迟的各个原因终于复出水面。在这个问题中，由于多个配置之间的互相作用最终导致了这个结果。主要有以下几点：

maxBatchSize 的默认值为 1
LocalTaskExecutorThreadPool 对于可用线程数永远返回 1
Quartz 的默认线程池是 SimpleThreadPool，但 Spring 在使用了自定义工作线程池的情况下默认为 LocalTaskExecutorThreadPool
org.quartz.threadPool.class 的默认行为与 Quartz 匹配，但与 Spring 不匹配

这里针对 3 多说几句。后面经过阅读代码，发现 Quartz 调度线程需要的 ThreadPool 并不是通常使用的 java.util.concurrent.ThreadPoolExecutor 而是 Quartz 自行封装的 org.quartz.spi.ThreadPool。因此，当我们要求 Spring 使用我们自定义的 ThreadPoolExecutor 来执行工作任务时，Spring 别无选择，必须对我们提供的 ThreadPoolExecutor 做一次封装，才能提供给 Quartz 调度线程使用。而一开始在编写代码时对这里没有深入研究则埋下了一个大坑。

因此这里的解决方案也很简单，直接去掉自定义线程池，使用 Quartz 提供的 SimpleThreadPool 来处理工作负载即可。而且这里修改为 Quartz 自身的 SimpleThreadPool 来处理工作负载后，原先的调度异常的问题也自然而然的解决了。具体原因见总结。修改配置后再进行测试，看到这样的日志输出：

[2021-04-17 15:50:09.821][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 0 triggers
[2021-04-17 15:50:33.989][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 50 triggers
[2021-04-17 15:51:01.551][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 50 triggers
[2021-04-17 15:51:02.948][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 50 triggers
[2021-04-17 15:51:04.009][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 6 triggers
[2021-04-17 15:51:04.723][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 44 triggers
[2021-04-17 15:51:06.241][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 50 triggers
[2021-04-17 15:51:07.614][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 26 triggers
[2021-04-17 15:51:08.500][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 31 triggers
[2021-04-17 15:51:09.448][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 43 triggers
[2021-04-17 15:51:10.600][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 31 triggers
[2021-04-17 15:51:11.564][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 19 triggers
[2021-04-17 15:51:11.884][|][quartz-scheduler_QuartzSchedulerThread] DEBUG o.quartz.core.QuartzSchedulerThread:run:291 - batch acquisition of 0 triggers

[2021-04-17 15:51:00.810][|][quartz-scheduler_Worker-5] Execute task|1|5
[2021-04-17 15:51:00.806][|][quartz-scheduler_Worker-3] Execute task|1|3
[2021-04-17 15:51:00.810][|][quartz-scheduler_Worker-20] Execute task|1|20
[2021-04-17 15:51:00.810][|][quartz-scheduler_Worker-21] Execute task|1|21
[2021-04-17 15:51:00.813][|][quartz-scheduler_Worker-22] Execute task|1|22
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-6] Execute task|1|6
[2021-04-17 15:51:00.810][|][quartz-scheduler_Worker-9] Execute task|1|9
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-12] Execute task|1|12
[2021-04-17 15:51:00.810][|][quartz-scheduler_Worker-17] Execute task|1|17
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-13] Execute task|1|13
[2021-04-17 15:51:00.818][|][quartz-scheduler_Worker-26] Execute task|1|26
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-23] Execute task|1|23
[2021-04-17 15:51:00.809][|][quartz-scheduler_Worker-4] Execute task|1|4
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-10] Execute task|1|10
[2021-04-17 15:51:00.809][|][quartz-scheduler_Worker-18] Execute task|1|18
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-8] Execute task|1|8
[2021-04-17 15:51:00.809][|][quartz-scheduler_Worker-19] Execute task|1|19
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-14] Execute task|1|14
[2021-04-17 15:51:00.807][|][quartz-scheduler_Worker-7] Execute task|1|7
[2021-04-17 15:51:00.807][|][quartz-scheduler_Worker-16] Execute task|1|16
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-11] Execute task|1|11
[2021-04-17 15:51:00.807][|][quartz-scheduler_Worker-15] Execute task|1|15
[2021-04-17 15:51:00.814][|][quartz-scheduler_Worker-1] Execute task|1|1
[2021-04-17 15:51:00.816][|][quartz-scheduler_Worker-24] Execute task|1|24
[2021-04-17 15:51:00.806][|][quartz-scheduler_Worker-2] Execute task|1|2
[2021-04-17 15:51:00.816][|][quartz-scheduler_Worker-25] Execute task|1|25
[2021-04-17 15:51:00.827][|][quartz-scheduler_Worker-27] Execute task|1|27
[2021-04-17 15:51:00.828][|][quartz-scheduler_Worker-31] Execute task|1|31
[2021-04-17 15:51:00.828][|][quartz-scheduler_Worker-29] Execute task|1|29
[2021-04-17 15:51:00.828][|][quartz-scheduler_Worker-32] Execute task|1|32
[2021-04-17 15:51:00.829][|][quartz-scheduler_Worker-30] Execute task|1|30
[2021-04-17 15:51:00.829][|][quartz-scheduler_Worker-28] Execute task|1|28
[2021-04-17 15:51:00.830][|][quartz-scheduler_Worker-33] Execute task|1|33
[2021-04-17 15:51:00.831][|][quartz-scheduler_Worker-35] Execute task|1|35
[2021-04-17 15:51:00.829][|][quartz-scheduler_Worker-34] Execute task|1|34
[2021-04-17 15:51:00.832][|][quartz-scheduler_Worker-36] Execute task|1|36
[2021-04-17 15:51:00.834][|][quartz-scheduler_Worker-37] Execute task|1|37
[2021-04-17 15:51:00.834][|][quartz-scheduler_Worker-38] Execute task|1|38
[2021-04-17 15:51:00.836][|][quartz-scheduler_Worker-41] Execute task|1|41
[2021-04-17 15:51:00.837][|][quartz-scheduler_Worker-39] Execute task|1|39
[2021-04-17 15:51:00.837][|][quartz-scheduler_Worker-40] Execute task|1|40
[2021-04-17 15:51:00.837][|][quartz-scheduler_Worker-42] Execute task|1|42
[2021-04-17 15:51:00.838][|][quartz-scheduler_Worker-43] Execute task|1|43
[2021-04-17 15:51:00.838][|][quartz-scheduler_Worker-44] Execute task|1|44
[2021-04-17 15:51:00.839][|][quartz-scheduler_Worker-45] Execute task|1|45
[2021-04-17 15:51:00.843][|][quartz-scheduler_Worker-48] Execute task|1|48
[2021-04-17 15:51:00.843][|][quartz-scheduler_Worker-46] Execute task|1|46
[2021-04-17 15:51:00.853][|][quartz-scheduler_Worker-49] Execute task|1|49
[2021-04-17 15:51:00.857][|][quartz-scheduler_Worker-47] Execute task|1|47
[2021-04-17 15:51:00.862][|][quartz-scheduler_Worker-50] Execute task|1|50

第一段调度器的日志显示现在已经成功的使用批量的方式来进行 Trigger 的拉取了，每次拉取 50 个。在拉取了 150 个任务之后，由于线程都已在执行任务，所以只有 6 个空闲线程释放，因此拉取了 6 个任务。

第二段是实际的任务执行日志。可以看到在这段执行过程中，大约有 25 个任务在 20ms 内启动完成，50 个任务全部启动也只消耗了约 50ms 的时间，已经比原先大大提升。

同时，对于负载不均匀的问题，在修改前，三台机器的负载为：1:2:497。修改之后再次测试，变为：100:151:249。负载不均匀的问题已经基本解决。

总结

注意事项

通过这次问题排查，认识到了一些在 Quartz 搭配 Spring 使用时需要注意的问题：

尽量不要使用自定义线程池，而是使用 Quartz 实现的 SimpleThreadPool
搭配使用时，不光要留意 Quartz 本身对于配置项的默认值处理，也要注意 Spring 对于配置项的处理
Quartz 的调度误差是由多方面原因造成的，需要综合考虑配置项之间的相互作用逻辑
分析问题时需要严格测试，而不能想当然的进行调整

调度异常&负载不均原因

另外再来看一下最开始遇到的调度异常&负载不均的问题。综合后续的所有分析可知，在默认情况下，Quartz 的调度逻辑是这样的：

可以看到在这个默认配置下，由于存在一个阻塞等待可用线程（org.quartz.simpl.SimpleThreadPool#blockForAvailableThreads）的操作，可以保证当本机的线程全部繁忙的时候，本机的调度线程不会去获取锁，自然而然的让别的实例来接手余下的任务调度工作。同时，由于这里的阻塞等待，保证了当本机线程全忙的时候不会有任何新任务进入，也就保证了不会出现提交失败的问题。

而当使用自定义线程池的时候，调度流程变成了这样：

在这个工作模式下，阻塞等待没有了。就算自定义线程池中的线程全忙、队列已满，此处还是会返回有一个可用线程。所以此时，调度线程的工作模式就变成了，不管线程池是否爆满，始终抢夺任务并继续提交。正是因为这里没有判定线程池是否满的逻辑，导致了最初的提交失败。而且由于不再等待可用线程，这里的循环变成了加锁->拉 Trigger->提交的循环，从而导致最初最先启动的线程在抢锁的过程中有极大的优势（没抢到锁会强制等待，而等待的时候锁已经又被最先启动的线程抢了），从而导致负载的严重失衡。

所以为了解决提交失败和负载不均的问题，最简单的方法是不要使用自定义线程池，而是通过 org.quartz.threadPool.class 设置使用 SimpleThreadPool，并根据机器负载调节线程数量。如果一定要使用自定义线程池的话，则必须实现 Quartz 提供的 org.quartz.spi.ThreadPool 接口，并实现阻塞等待可用线程的逻辑。千万不能直接使用 Spring 提供的 LocalTaskExecutorThreadPool。

调度延迟产生的原因

根据本次分析的过程可以看出，Quartz 的调度延迟主要由以下几个方面组成：

同步加锁延迟。当 Quartz 使用DB作为集群持久化存储的场景下，为了保证调度秩序，避免重复调度或漏调度，每一次 DB 操作都要进行加锁。而每次调度时，需要先从 DB 读取要触发的 Trigger 信息并更新状态为 ACQUIRED，然后在将要触发时更新状态到 EXECUTING，之后才会向工作线程池提交任务。虽然在读取 Trigger 信息的时候大部分操作都不是批量进行的，但是加锁操作是针对一批任务的。考虑到正常的 DB 读写耗时在 5～10ms 左右，如果不进行批量操作的话，按照 50 个任务一批计算，每一批的加锁时间就白白增加了 250～500ms。因此，进行批量拉取可以有效的减小 DB 加锁操作带来的调度延迟。同时，考虑到锁的竞争会导致线程等待，批量加锁操作还可以有效的降低锁争抢，提升整体效率。如果业务场景对调度延迟比较敏感，应考虑使用性能更好的独立 DB 实例，并尽量降低 Quartz 实例到 DB 之间的网络延迟；
批量执行排队延迟。如果同时触发的任务数量超过了总集群的线程池上限，则一定会被分为多个批次进行触发，这时就会出现排队延迟。这里每个批次间的排队延迟将取决于任务的执行速度。单个任务执行的越慢则越靠后被触发的批次延迟越大。当总线程数耗尽时，下一次调度一定会等到有线程释放才会开始。理想情况下所有任务都应在一个批次内做完。因此应根据工作负载的情况，对 Quartz 集群进行扩容，增加总线程数，来避免任务进入排队。但是由于成本限制，这个方式往往很难实施。而且在实际使用的过程中，偶尔会出现任务本身的执行耗时不可控的情况。因此在实际使用的过程中，需要根据实际的业务情况，合理调节批量参数和工作线程数。当然在调节工作线程数量时还需要需要考虑到机器实际的负载能力，不能无谓的提高，反而导致负载不均衡的情况出现。同时应当考虑采取异步机制，并通过消息队列等异步化手段，将任务快速分发下去。再结合快速扩容机制，在峰值来临前对执行器进行扩容，来进一步降低延迟。这里推荐异步化任务执行器而不是大量扩容 Quartz 集群的主要原因在于，Quartz 集群本身是一个有状态的集群，相对来说逻辑复杂、任务较重，且存在集群锁，不适合进行快速扩缩容。而在需要大批量调度的场景下，我们的工作负载往往都是无状态、逻辑简单、轻量化的小任务。这种任务最适合配合 K8S 等集群进行快速扩容支撑峰值，并在谷时缩容降低成本；
CPU调度延迟。当调度线程将任务提交给工作线程池后，工作线程池中的线程最终还需要依赖 CPU 时间片来执行，若调度机器的 CPU 负载较高，或线程池数量不合理，那么线程在真正被 CPU 执行前将会有较大等待。为了尽量减少这里的执行延迟，应将工作线程池部署在 CPU 核数较多且负载不高的机器上。同时应该合理设置工作线程数量，避免一次性触发过多任务。

2024 年 11 月
日	一	二	三	四	五	六
					1	2
3	4	5	6	7	8	9
10	11	12	13	14	15	16
17	18	19	20	21	22	23
24	25	26	27	28	29	30