背景

最近在負(fù)責(zé)開(kāi)發(fā)維護(hù)的一款數(shù)據(jù)平臺(tái)，有一個(gè)功能是把數(shù)據(jù)從某個(gè)源頭數(shù)據(jù)源（如常規(guī)的JDBC數(shù)據(jù)源，MySQL，Oracle等）推到目地?cái)?shù)據(jù)源（還包括企微，MQ等）。一次推送數(shù)據(jù)就是一個(gè)任務(wù)，當(dāng)然需要記錄此次推送任務(wù)的執(zhí)行情況，如任務(wù)的開(kāi)始時(shí)間，結(jié)束時(shí)間，任務(wù)名稱，任務(wù)執(zhí)行狀態(tài)，任務(wù)日志（失敗原因），執(zhí)行人，執(zhí)行方式（手動(dòng)執(zhí)行還是定時(shí)觸發(fā)）。另外，從來(lái)源數(shù)據(jù)源取數(shù)，怎么取數(shù)是通過(guò)SQL指定的，那我們還可以記錄一下SQL查詢耗時(shí)，以及SQL查詢條數(shù)。總耗時(shí)就是任務(wù)執(zhí)行結(jié)束時(shí)間減去任務(wù)開(kāi)始時(shí)間，總耗時(shí)肯定大于SQL查詢耗時(shí)。

統(tǒng)計(jì)SQL查詢耗時(shí)時(shí)，還需要考慮到SQL取數(shù)的數(shù)據(jù)量，假如SQL查詢量為1000w，程序不可能一次查詢?nèi)繑?shù)據(jù)，然后加工處理并發(fā)送到下游目地?cái)?shù)據(jù)源，故而需要設(shè)置分批。假設(shè)批次為50w，則SQL查詢耗時(shí)為20次查詢的耗時(shí)之和。

扯遠(yuǎn)一句，項(xiàng)目是接手維護(hù)的，一開(kāi)始的設(shè)計(jì)開(kāi)發(fā)者是用秒來(lái)記錄SQL查詢耗時(shí)，這樣一看就不嚴(yán)謹(jǐn)，因?yàn)楹芏郤QL查詢耗時(shí)根本不需要1秒。事實(shí)上就算查詢耗時(shí)超過(guò)1s，1.6s和1.7s也是有區(qū)別的，故而需要帶毫秒來(lái)優(yōu)化記錄SQL查詢耗時(shí)。最后在前端展示時(shí)，用小數(shù)點(diǎn)來(lái)表示毫秒。

很常規(guī)，看起來(lái)也沒(méi)有任何問(wèn)題的數(shù)據(jù)表設(shè)計(jì)：

create table execlog (
    id             bigint(11) auto_increment primary key,
    total_sql_time bigint                                  null comment 'SQL執(zhí)行耗時(shí)，單位豪秒',
    start_date     timestamp default CURRENT_TIMESTAMP not null comment '執(zhí)行開(kāi)始時(shí)間',
    end_date       timestamp                               null comment '執(zhí)行結(jié)束時(shí)間',
);

注：total_sql_time注釋單位毫秒，以及程序記錄單位是后來(lái)優(yōu)化調(diào)整的。

某次任務(wù)執(zhí)行記錄截圖如下，發(fā)現(xiàn)總耗時(shí)為0秒，而查詢耗時(shí)為146毫秒。這顯然不符合邏輯。

優(yōu)化

優(yōu)化思路也不難，就是任務(wù)開(kāi)始時(shí)間需要記錄到毫秒級(jí)別，改進(jìn)后的表結(jié)構(gòu)為：

create table execlog (
    id             bigint(11) auto_increment primary key,
    total_sql_time bigint                                    null comment 'SQL執(zhí)行耗時(shí)，單位豪秒',
    start_date     timestamp(3) default CURRENT_TIMESTAMP(3) not null comment '執(zhí)行開(kāi)始時(shí)間',
    end_date       timestamp(3)                                  null comment '執(zhí)行結(jié)束時(shí)間',
);

值得注意的是，MySQL直到版本5.6（不太確定）才支持，如何知道自己使用的MySQL Server版本是否支持timestamp(3)，執(zhí)行語(yǔ)句即可驗(yàn)證，沒(méi)有報(bào)錯(cuò)并且返回毫秒數(shù)表示支持：select now(3);

優(yōu)化上面截圖中的日志記錄問(wèn)題分為兩個(gè)步驟，即日志記錄和日志顯示。

日志記錄

增加一個(gè)取當(dāng)時(shí)時(shí)間精確到毫秒的靜態(tài)方法：

public static final String COMMON_DATE_WITH_MILLI_SECOND = "yyyy-MM-dd HH:mm:ss:sss";

public static String getNowWithMilliSecond() {
    SimpleDateFormat sdf = new SimpleDateFormat(Constant.COMMON_DATE_WITH_MILLI_SECOND);
    return sdf.format(new Date());
}

表結(jié)構(gòu)如上改進(jìn)后，發(fā)現(xiàn)start_date記錄沒(méi)有問(wèn)題，帶3位小數(shù)點(diǎn)。但end_date記錄不到小數(shù)點(diǎn)，即未記錄到毫秒，于是懷疑表結(jié)構(gòu)不對(duì)。

某次任務(wù)執(zhí)行肯定會(huì)有start_date，故而設(shè)置為not null，但會(huì)因發(fā)布，或調(diào)試中斷等各種原因?qū)е掠涗洸坏?code>end_date時(shí)間點(diǎn)，因此字段不能設(shè)置為not null。

落不到數(shù)據(jù)，懷疑需要給一個(gè)默認(rèn)值，于是如下改表結(jié)構(gòu)

create table execlog (
    id             bigint(11) auto_increment primary key,
    start_date     timestamp(3) default CURRENT_TIMESTAMP(3) not null comment '執(zhí)行開(kāi)始時(shí)間',
	end_date       timestamp(3) default CURRENT_TIMESTAMP(3) null comment '執(zhí)行結(jié)束時(shí)間'
);

但是還是記錄不到結(jié)束時(shí)間的毫秒數(shù)。

此時(shí)只能好好看代碼，end_date是在任務(wù)結(jié)束（不管是正常結(jié)束還是異常結(jié)束，異常結(jié)束在finally語(yǔ)句塊）時(shí)updateExecLog更新：

<update id="updateExecLog" parameterType="com.xy.cloudiview.common.po.ExecLog">
    UPDATE execlog t
    <set>
        <if test="errorLog != null">
            t.error_log = #{errorLog},
        </if>
        t.end_date = now(),
    </set>
    WHERE t.id = #{id}
</update>

此處已經(jīng)指定end_date取數(shù)為now()，肯定不會(huì)記錄到毫秒數(shù)的。需改成t.end_date = now(3),。

再看另外一個(gè)updateExecLog更新語(yǔ)句：

<update id="updateByPrimaryKeySelective" parameterType="com.xy.cloudiview.common.po.ExecLogWithBlobs">
    update execlog
    <set>
        <if test="endDate != null">
            end_date = #{endDate,jdbcType=TIMESTAMP},
        </if>
    </set>
    where id = #{id,jdbcType=BIGINT}
</update>

貌似找到一點(diǎn)問(wèn)題解決思路，開(kāi)啟MySQL日志打印功能：

mybatis:
  configuration:
    log-impl: org.apache.ibatis.logging.stdout.StdOutImpl

一個(gè)很無(wú)厘頭的嘗試：

<if test="endDate != null"> end_date = #{endDate,jdbcType=TIMESTAMP(3)},</if>

報(bào)錯(cuò)：

MyBatisSystemException: nested exception is org.apache.ibatis.builder.BuilderException: Error resolving JdbcType. Cause: java.lang.IllegalArgumentException: No enum constant org.apache.ibatis.type.JdbcType.TIMESTAMP(3)
    at java.lang.Enum.valueOf(Enum.java:238)

那就把jdbcType去掉：

<if test="endDate != null">
    end_date = #{endDate},
</if>

打印日志如下：

JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@7ef24deb] will not be managed by Spring
==>  Preparing: update execlog SET end_date = ? where id = ? 
==> Parameters: 2022-10-12 17:08:13:013(String), 31542157(Long)
nested exception is com.mysql.cj.jdbc.exceptions.MysqlDataTruncation: Data truncation: Incorrect datetime value: '2022-10-12 16:05:47:047' for column 'end_date' at row 1

也就是說(shuō)，當(dāng)MyBatis遇到MySQL timestamp(3)時(shí)，MyBatis上面這種寫法支持不了。

于是只能換一種寫法：

<update id="updateByPrimaryKeySelective" parameterType="com.xy.cloudiview.common.po.ExecLogWithBlobs">
    update execlog
    <set>
    	<if test="modelId != null">
            model_id = #{modelId,jdbcType=BIGINT},
        </if>
		end_date = now(3),
    </set>
    where id = #{id,jdbcType=BIGINT}
</update>

解決問(wèn)題。也不需要在Java代碼層設(shè)置帶毫秒數(shù)的當(dāng)前時(shí)間。

此時(shí)，回頭看看第一個(gè)截圖，里面有一個(gè)日志類型的字段，文章開(kāi)頭沒(méi)有描述。這里解釋一下，因?yàn)槠脚_(tái)有多種類型的任務(wù)，涉及多個(gè)maven Module模塊和多個(gè)表，于是有多個(gè)execlog的insert和update語(yǔ)句。

再來(lái)看一個(gè)insertExecLog語(yǔ)句，省略無(wú)關(guān)字段，這種方法是MyBatis插件generator自動(dòng)生成的，也沒(méi)有任何問(wèn)題，就是看起來(lái)非常冗余，兩個(gè)<trim>語(yǔ)句塊，再加上每個(gè)<trim>語(yǔ)句塊里面每個(gè)字段都有<if>語(yǔ)句塊條件判斷語(yǔ)句：

<insert id="insertSelective" parameterType="com.xy.cloudiview.common.po.ExecLogWithBlobs">
  <selectKey resultType="java.lang.Long" keyProperty="id" order="AFTER">
        SELECT LAST_INSERT_ID()
    </selectKey>
    insert into execlog
    <trim prefix="(" suffix=")" suffixOverrides=",">
        <if test="startDate != null">
            start_date,
        </if>
    </trim>
    <trim prefix="values (" suffix=")" suffixOverrides=",">
        <if test="startDate != null">
            #{startDate,jdbcType=TIMESTAMP},
        </if>
    </trim>
</insert>

維護(hù)項(xiàng)目的一個(gè)默認(rèn)的潛規(guī)則，就是除非沒(méi)有大的問(wèn)題，盡可能不要大面積改動(dòng)代碼，大面積改動(dòng)還不如重構(gòu)，重構(gòu)的前提是對(duì)項(xiàng)目非常了解。

當(dāng)然這個(gè)地方只是一個(gè)MyBatis方法而已，還達(dá)不到重構(gòu)那個(gè)深度。但是我也是想著盡可能不要改動(dòng)太多，于是改動(dòng)如下：

<insert id="insertSelective" parameterType="com.xy.cloudiview.common.po.ExecLogWithBlobs">
  <selectKey resultType="java.lang.Long" keyProperty="id" order="AFTER">
        SELECT LAST_INSERT_ID()
    </selectKey>
    insert into execlog
    <trim prefix="(" suffix=")" suffixOverrides=",">
        start_date,
    </trim>
    <trim prefix="values (" suffix=")" suffixOverrides=",">
        now(),
    </trim>
</insert>

報(bào)錯(cuò)信息就不貼出來(lái)了，原因還是當(dāng)MyBatis遇到MySQL timestamp(3)時(shí)，MyBatis上面這種寫法不支持。

改動(dòng)方法：

刪除start_date對(duì)應(yīng)的if判斷語(yǔ)句塊，讓MySQL的default CURRENT_TIMESTAMP(3)來(lái)使其生效

使用如下方法：

<insert id="saveExecLog" parameterType="com.xy.cloudiview.common.po.ExecLogWithBlobs">
    INSERT INTO execlog(start_date) VALUES (now(3))
</insert>

日志查詢

改進(jìn)前的執(zhí)行日志列表頁(yè)查詢語(yǔ)句為：

select 
DATE_FORMAT(t.start_date,'%Y-%m-%d %H:%i:%s') as startDate,
TO_SECONDS(t.end_date)-TO_SECONDS(t.start_date) as totalTime
from execlog

改進(jìn)后的：

select
SUBSTRING(DATE_FORMAT(t.end_date, '%Y-%m-%d %H:%i:%s.%f'), 1, 23) AS endDate,
TIMESTAMPDIFF(MICROSECOND, t.start_date, t.end_date) / (1000 * 1000) AS totalTime
from execlog

最后實(shí)現(xiàn)的效果是：

參考

get-milliseconds-with-date-format-in-mysql
https://stackoverflow.com/questions/26299149/timestamp-with-a-millisecond-precision-how-to-save-them-in-mysql
https://stackoverflow.com/questions/20520443/mysql-timestamp-to-default-null-not-current-timestamp

到此這篇關(guān)于淺談MySQL timestamp(3)問(wèn)題的文章就介紹到這了,更多相關(guān)MySQL timestamp(3)內(nèi)容請(qǐng)搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關(guān)文章希望大家以后多多支持腳本之家！

最新評(píng)論