Sequelize ORM 高并发实战

Sequelize ORM 高并发实战

image.png

Sequelize 是一款优秀的数据库 ORM
框架,支持 mysql、postgres、sqlite、mariadb、mssql。使用方法非常灵活多变,GitHub star 数目前 20k 左右,其周边工具 sequelize-auto 可自动从数据库生成模型文件,sequelize-cli 可以依据模型文件创建数据库,能力非常强大。

前言

目前在 CAS Node 项目中,基本上都是用的这个 ORM 来和 MSSQL 进行交互访问,如果没有高并发访问冲击的情况下,一般使用这个 ORM 第三库不会出现什么性能问题。但是遇到需要频繁操作 DB ,就可能会做成生产环境上面 DB DTU HIGH 的行为。

image.png100% DTU Usage

架构图一览

目前 CAS 处理 ATP DP Policy Detection Mail 架构图如下所示:

image.png

##

问题定位

我们目前使用的是 Azure MSSQL DB,生产环境中从它自带的监控后台我们可以查看到每个语句的查看次数以及那些语句导致了 High DTU 的问题。

初定位

根据 OP 同学的给出的反馈,我们发现到线上有一个查询语句时间过长,在此时间点 DB 的 DTU 也非常高,这时候我们怀疑是这条语句导致的。
image.pngimage.png

1
(@1 varchar(8000))SELECT [NTF_ADMIN_SUBJECT],[NTF_TO_ACCOUNT],[NTF_ADMIN_MESSAGE],[NTF_ADMIN_NOTIFY_SETTING_TYPE],[NTF_ADMIN_INTERVAL_TYPE],[NTF_ADMIN_INTERVAL_NUM],[NTF_ADMIN_OCCURENCE_NUM],[NTF_EVENTS_OCCURENCE_NUM] FROM [tm_atp_dp_notification] WHERE [cfg_index]=@1

验证再定位

通过对于逻辑进行优化,减少这条语句的查询次数来优化,通过此类优化至生产环境发现效果并没有得到明显改善。在本地通过执行计划来看语句的查询时间,发现它走的是 Cluster Index,单机速度非常快。
image.png

由此得出问题点可能不是出于这个查询语句,这时候想到我们可以通过在数据库里面查找慢查询语句来定位问题。

1
2
3
4
5
平均耗 CPU 最多的前个 SQL (SQL SERVER 2005或以上版本)
USE [tmcas-dev]
GO

SELECT TOP 5 total_worker_time / execution_count AS [Avg CPU Time], SUBSTRING(st.text, (qs.statement_start_offset/2)+1, ((CASE qs.statement_end_offset WHEN -1 THEN DATALENGTH(st.text) ELSE qs.statement_end_offset END - qs.statement_start_offset)/2) + 1) AS statement_text FROM sys.dm_exec_query_stats AS qs CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) AS st ORDER BY total_worker_time/execution_count DESC

实践验证

模拟生产环境场景,处理 1000 条邮件,来查看 DB 的慢查询情况。

测试脚本

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
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
/*
Copyright (c) Microsoft Corporation. All rights reserved.
Licensed under the MIT Licence.

This sample demonstrates how the send() function can be used to send messages to Service Bus
Queue/Topic.
See https://docs.microsoft.com/en-us/azure/service-bus-messaging/service-bus-queues-topics-subscriptions
to learn about Queues, Topics and Subscriptions.
*/

const { ServiceBusClient } = require("@azure/service-bus");

const listOfScientists = [
{
cfg_index: 'WTP-72e17cc0-7502-4074-bf4e-b10605091995',
tm_company_guid: '65942380-19e2-11e7-94a3-3dbfff631318',
ntf_enable_notify_admin: 1,
ntf_enable_notify_user: 0,
ntf_admin_notify_setting_type: 0,
ntf_admin_interval_type: 0,
ntf_admin_interval_num: 2,
ntf_admin_occurence_num: 3,
ntf_admin_to_account: 'jack_sun@trendmicro.com',
ntf_admin_subject:
'VHJlbmQgTWljcm8gQ2xvdWQgQXBwIFNlY3VyaXR5IEFkdmFuY2VkIFRocmVhdCBQcm90ZWN0aW9uIHR0dHR0dHR0dA==',
ntf_admin_message:
'Q2xvdWQgQXBwIFNlY3VyaXR5IGRldGVjdGVkIGFuIGVtYWlsIG1lc3NhZ2Ugd2l0aCBhIHN1c3BpY2lvdXMgVVJMLg0KDQpVUkw6IFtodHRwXTpbL11bL113cnMyMVsuXXdpbnNoaXB3YXlbLl1jb20NClJpc2sgbGV2ZWw6IERhbmdlcm91cw0KQWN0aW9uIHRha2VuOiBRdWFyYW50aW5lDQpNZXNzYWdlIGRldGFpbHM6DQoJUmVjZWl2ZWQ6IDIwMTkvMDkvMDYgMDQ6NTU6MzQgKFVUQykNCglGb3VuZCBpbjogbWl0aWdhdGlvbi10ZXN0QHRtZGV2b3JnLm9ubWljcm9zb2Z0LmNvbVxJbmJveA0KCVRyaWdnZXJlZCBwb2xpY3k6IGVtYWlsLXRlc3QNCglEZXRlY3RlZCBieTogV2ViIFJlcHV0YXRpb24NCglTZW5kZXI6ICJJY2VraW5nIENoZW4iPGljZWtpbmdfY2hlbkB0bWRldm9yZy5vbm1pY3Jvc29mdC5jb20+DQoJUmVjaXBpZW50OiAibWl0aWdhdGlvbiB0ZXN0IjxtaXRpZ2F0aW9uLXRlc3RAdG1kZXZvcmcub25taWNyb3NvZnQuY29tPg0KCVN1YmplY3Q6IGh0dHA6Ly93cnMyMS53aW5zaGlwd2F5LmNvbS8NCglDYXRlZ29yeTogU3B5d2FyZQ==',
ntf_user: 'mitigation-test@tmdevorg.onmicrosoft.com',
ntf_user_subject:
'VHJlbmQgTWljcm8gQ2xvdWQgQXBwIFNlY3VyaXR5IEFkdmFuY2VkIFRocmVhdCBQcm90ZWN0aW9u',
ntf_user_message:
'Q2xvdWQgQXBwIFNlY3VyaXR5IGRldGVjdGVkIGFuIGVtYWlsIG1lc3NhZ2Ugd2l0aCBhIHN1c3BpY2lvdXMgVVJMLCBhbmQgdG9vayBhY3Rpb24gb24gaXQgdG8gY29tcGx5IHdpdGggdGhlIGluZm9ybWF0aW9uIHNlY3VyaXR5IHBvbGljaWVzIG9mIHRoZSBvcmdhbml6YXRpb24uDQoNClVSTDogW2h0dHBdOlsvXVsvXXdyczIxWy5dd2luc2hpcHdheVsuXWNvbQ0KUmlzayBsZXZlbDogRGFuZ2Vyb3VzDQpBY3Rpb24gdGFrZW46IFF1YXJhbnRpbmUNCk1lc3NhZ2UgZGV0YWlsczoNCglSZWNlaXZlZDogMjAxOS8wOS8wNiAwNDo1NTozNCAoVVRDKQ0KCUZvdW5kIGluOiBtaXRpZ2F0aW9uLXRlc3RAdG1kZXZvcmcub25taWNyb3NvZnQuY29tXEluYm94DQoJVHJpZ2dlcmVkIHBvbGljeTogZW1haWwtdGVzdA0KCURldGVjdGVkIGJ5OiBXZWIgUmVwdXRhdGlvbg0KCVNlbmRlcjogIkljZWtpbmcgQ2hlbiI8aWNla2luZ19jaGVuQHRtZGV2b3JnLm9ubWljcm9zb2Z0LmNvbT4NCglSZWNpcGllbnQ6ICJtaXRpZ2F0aW9uIHRlc3QiPG1pdGlnYXRpb24tdGVzdEB0bWRldm9yZy5vbm1pY3Jvc29mdC5jb20+DQoJU3ViamVjdDogaHR0cDovL3dyczIxLndpbnNoaXB3YXkuY29tLw0KCUNhdGVnb3J5OiBTcHl3YXJlDQoNCg==',
ntf_ws_expected_sender: '',
ntf_enable_notify_ws_expected_sender: 0,
ntf_ws_notify_expected_sender_attach_origin_mail_enabled: 0,
ntf_enable_notify_ws_admin: 0,
ntf_ws_notify_admin_attach_origin_mail_enabled: 0,
ntf_ws_expected_sender_subject: '',
ntf_ws_expected_sender_message: '',
ntf_ws_admin_subject: '',
ntf_ws_admin_message: '',
ntf_ws_unique_id: '',
ntf_ws_mailbox: 'mitigation-test@tmdevorg.onmicrosoft.com',
ntfEnableEndUserRestore: 0,
serviceType: 'Exchange Online',
trace_id:
'mitigation-test@tmdevorg.onmicrosoft.com@@<HK2PR0601MB1940A2B7964C893C425D0891C1BA0@HK2PR0601MB1940.apcprd06.prod.outlook.com>@@0d188dde4732c6b652ab6a1d6c2de224@@1'
}
];

async function main() {
const sbClient = ServiceBusClient.createFromConnectionString("xx");

// If sending to a Topic, use `createTopicClient` instead of `createQueueClient`
const queueClient = sbClient.createQueueClient("cas-notification-queue");
const sender = queueClient.createSender();

try {
for (let index = 0; index < 1000; index++) {
const scientist = listOfScientists[0];
const message = {
body: scientist,
};

console.log(`Sending message: ${message.body}`);
await sender.send(message);
}

await queueClient.close();
} finally {
await sbClient.close();
}
}

main().catch((err) => {
console.log("Error occurred: ", err);
});

DB 慢查询

image.png

DB DTU

image.png

从上面两张图基本可以定位到引起 DTU 高的“元凶”了,也就是引起慢查询的这条 UPDATE 语句。

1
UPDATE [tm_atp_dp_notification] SET [NTF_ADMIN_MESSAGE]=CONCAT([NTF_ADMIN_MESSAGE], N'Cloud App Security detected an email message with a suspicious URL.<br /><br />URL: [http]:[&#047;][&#047;]wrs21[.]winshipway[.]com<br />Risk level: Dangerous<br />Action taken: Quarantine<br />Message details:<br /> Received: 2019&#047;09&#047;06 04:55:34 (UTC)<br />     Found in: mitigation-test@tmdevorg.onmicrosoft.com\Inbox<br />  Triggered policy: email-test<br />  Detected by: Web Reputation<br />        Sender: &quot;Iceking Chen&quot;&lt;iceking_chen@tmdevorg.onmicrosoft.com&gt;<br />     Recipient: &quot;mitigation test&quot;&lt;mitigation-test@tmdevorg.onmicrosoft.com&gt;<br />    Subject: http:&#047;&#047;wrs21.winshipway.com&#047;<br />   Category: Spyware<br /><br />'),[NTF_EVENTS_OCCURENCE_NUM]=NTF_EVENTS_OCCURENCE_NUM + 1,[UPDATED_AT]=N'2019-09-20 07:17:26.787 +00:00' OUTPUT INSERTED.* WHERE [CFG_INDEX] = N'WTP-72e17cc0-7502-4074-bf4e-b10605091995'

它做了什么事情呢?它主要是利用 CONCAT 语法将列连接起来,并且更新时间戳,单条语句去执行的时候,它的执行计划如下:
image.png

咋一看没有什么问题,语句的 COST 时间也非常短。这时候想到了查看 Account 服务对于数据库的连接池情况,可以通过下列语句来进行查看。

1
SELECT HOSTNAME,COUNT(1) LINKNUM from sysprocesses where dbid in (select dbid from sysdatabases where name='tmcas-dev') GROUP BY HOSTNAME

通过观察发现,当前 Account 消费邮件超过 500 之后,数据库的连接数就一直往上涨,如下图所示,一直涨到 88,相比于其他服务这是非常吓人的,

image.png

与此同时我们发现 Node 在服务器中消耗的内存也在一直飙升,一直升到 500 M 触发了 PM2 的自动重启,这时候服务重启,所有的 DB Connection 重置,又继续处理邮件。
image.png

这也侧面验证了,我们从 US 生产环境来看,有将近 12 K 的 Message 没有能被正常消费,也是因为服务处理异常导致的数据库连接超时, 从而使得 Message Handle Exception
image.png

回到初衷,性能优化

我们从上面实践中不难发现,当数据库的某一列过大时,在此频繁更新这一列速度会非常慢,引起 Sequelize 对于 Azure DB 的连接超时,熟悉数据库连接池的小伙伴应该知道,数据库的连接在处理数据非常快的情况下是可以复用的,但是一旦出现连接超时,这时候就会生成一条新的连接进行数据库访问。从实践中我们可以发现,一旦出现超时情况发生,不采取响应的策略的话,连接数就会一直飙升,知道连接池耗慢服务重启。

业务层面优化

从架构图上面我们可以得知,当 consolidate time mail 的最大限制是 998,也就是极端情况下这一列长度有 998 封邮件,如果可以降低这个数值至 500,也就可以减少数据库连接数,使得它存在空闲的连接可以复用,这带来的风险就是我们发送的邮件数会增多。

技术层面优化

分表,拆分这个频繁更新的列
image.png