一個SQL錯誤的問題讓我找到了公司框架中三個Bug
本文是對之前開發(fā)中遇到的問題的一個總結(jié)，文章其實早就寫好，但是覺得自己寫得不夠深入，就讓文章一直躺在草稿箱里。昨天突然想起來了，就將文章重新修改了一下，還是發(fā)出來吧!
問題1
當(dāng)時我在開發(fā)一個異常日志記錄接口，其實業(yè)務(wù)流程很簡單，就是前端提交錯誤日志到后臺，后臺接受到信息處理一番，然后插入數(shù)據(jù)庫。因為這個接口的并發(fā)量比較高，為了不影響其他業(yè)務(wù)，并且同時提高響應(yīng)的速度。于是采用 @Async 注解+ Spring線程池的方案來實現(xiàn)。線程池的配置如下：
- <task:annotation-driven executor="jobExecutor"/>
- <task:executor id="jobExecutor" pool-size="20" queue-capacity="500" />
使用 task:annotation-driven/ 開啟異步時，一定要記得配置executor屬性，不然異步使用的線程池其實是
org.springframework.core.task.SimpleAsyncTaskExecutor ，但這個 SimpleAsyncTaskExecutor 不是真的線程池，這個類不重用線程，每次調(diào)用都會創(chuàng)建一個新的線程。
關(guān)鍵部分偽代碼如下：
- @Async
- public void test(){
- ExceptionLogEntity exceptionLogEntity = new ExceptionLogEntity();
- exceptionLogEntity.setXX("");
- exceptionLogEntity.setXXX("");
- exceptionLogEntity.setIp("");
- exceptionLogEntity.setUrl("");
- exceptionLogEntity.setBusinessScene("");
- exceptionLogEntity.setExceptionType("");
- exceptionLogEntity.setExceptionDetailType("");
- exceptionLogEntity.setExceptionMessage("");
- exceptionLogEntity.setNoticeStatus("");
- exceptionLogEntity.setCreateTime(new Date());
- exceptionLogEntity.setUpdateTime(new Date());
- ExceptionLogEntity insert = exceptionLogDao.insert(exceptionLogEntity);
- log.info("實體的主鍵id=[{}]", insert.getId());
- }
代碼寫完我簡單的測試了一下，沒啥問題后就告知前端可以對接了。可是奇怪的事情發(fā)生了，前端老鐵告訴我接口有時會返回錯誤。我一聽就感覺不對勁，心想這么簡單的接口，我怎么可能有bug。于是我到日志平臺上查詢了一下日志，結(jié)果還真的是有問題。發(fā)現(xiàn)了一個SQL錯誤，具體錯誤如下(敏感信息已經(jīng)處理)：
- Caused by: java.lang.reflect.InvocationTargetException
- INSERT INTO `xx`(`xx`,`xx`,`ip`,`url`,`business_scene`,`exception_type`,`exception_detail_type`,`exception_message`,`notice_status`,`create_time`,`update_time`,`xx`,`member_phone`,`ip`,`url`,`business_scene`,`exception_type`,`exception_detail_type`,`exception_message`,`notice_status`,`create_time`,`update_time`) VALUES('','','','','','','','','','2020-01-08 19
- at sun.reflect.GeneratedMethodAccessor115.invoke(Unknown Source)
- --------------------------------------------
- at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
- at java.lang.reflect.Method.invoke(Method.java:498)
- at coderead.mybatis.log.JdbcCommonCollects$PreparedStatementHandler.invoke(JdbcCommonCollects.java:118)
- ... 21 more
- Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Column 'update_time' specified twice
- at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
- at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
- at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
- at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
- at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
復(fù)現(xiàn)問題
這個問題簡單的來說就是SQL中的字段發(fā)生了重復(fù)， Column 'update_time' specified twice。其實不止update_time字段發(fā)生了重復(fù)，是很多字段都發(fā)生了重復(fù)。因為這個接口除了并發(fā)高一點之外，和其他的接口沒有什么特別之處!突然我腦子里靈光一閃，難道是這個接口并發(fā)較高，導(dǎo)致框架在生成INSERT類型的SQL發(fā)生了錯誤???要是這樣的話，我直接創(chuàng)造一個這樣的場景不就可以實現(xiàn)了嘛!然后我寫下了下面的代碼：
- public void test(){
- for (int i = 0; i < 1000; i++) {
- ExceptionLogEntity exceptionLogEntity = new ExceptionLogEntity();
- exceptionLogEntity.setXX("");
- exceptionLogEntity.setXXX("");
- exceptionLogEntity.setIp("");
- exceptionLogEntity.setUrl("");
- exceptionLogEntity.setBusinessScene("");
- exceptionLogEntity.setExceptionType("");
- exceptionLogEntity.setExceptionDetailType("");
- exceptionLogEntity.setExceptionMessage("");
- exceptionLogEntity.setNoticeStatus("");
- exceptionLogEntity.setCreateTime(new Date());
- exceptionLogEntity.setUpdateTime(new Date());
- Thread thread = new Thread(() -> {
- exceptionLogDao.insert(exceptionLogEntity);
- });
- thread.start();
- }
- }
代碼寫完直接重啟項目，最后一觸發(fā)上面的代碼。果然，同樣的錯誤又出現(xiàn)了。這里我先介紹下使用的ORM框架：
此ORM框架是集團(tuán)O2O研發(fā)中心研發(fā)的基礎(chǔ)組件，提供同Mybatis一樣的功能：只需定義接口，無需寫實現(xiàn)類。此外，對單表操作還封裝了一套常用的增刪改查處理，連接口也無需再定義，對開發(fā)人員非常友好，大大降低了冗長的jdbc操作代碼量，提升了開發(fā)效率。
我問了問旁邊的同事，在使用公司的ORM框架自帶的INSERT方法時，有沒有遇到SQL列重復(fù)的問題嗎?嘿你還別說，大家異口同聲說遇到過。那厲害了，看來這真的不是個別現(xiàn)象，真的是框架的bug。于是乎我花了一點時間來找找看到底是在哪個地方出現(xiàn)了問題，皇天不負(fù)有心人我還真的找到了，具體的代碼如下：
- public List<DalColumn> getDalColumnsWithoutId() {
- if (this.columnsWithoutId != null) {
- return this.columnsWithoutId;
- } else {
- this.columnsWithoutId = new ArrayList(this.dalColumns.size() - 1);
- Iterator var1 = this.dalColumns.iterator();
- while(var1.hasNext()) {
- DalColumn column = (DalColumn)var1.next();
- if (!column.isIdColumn()) {
- this.columnsWithoutId.add(column);
- }
- }
- return this.columnsWithoutId;
- }
- }
問題就出在 columnsWithoutId 上，它的類型是 List ，是所在類的一個屬性默認(rèn)為null，保存的是一個表除主鍵ID之外的所有字段。上面的代碼在單線程情況下沒有問題，但是在多線程的情況下就問題大了。 columnsWithoutId 在多線程情況下就是一個 線程共享變量 ，假設(shè)在某個時機(jī)有多個線程恰好執(zhí)行到 if 代碼塊，發(fā)現(xiàn) columnsWithoutId 的值為null，則就會同時執(zhí)行 else代碼塊，那這時就會執(zhí)行多次循環(huán)，自然 columnsWithoutId 中的字段就會出現(xiàn)了重復(fù)。
解決問題
這個問題已經(jīng)找到，那接下來就差一個解決方案了。
官方修復(fù)
我當(dāng)時想既然這個框架是公司研發(fā)中心提供的基礎(chǔ)組件，那就是說明在公司內(nèi)部會有很多項目組使用，問題說不定早就被修復(fù)了。你還別說在公司的wiki上我還真的找到了，有位負(fù)責(zé)這個組件的大佬在wiki上分享了”單表插入偶發(fā)列重復(fù)問題定位與解決”的文章。(文章地址我就不發(fā)了，公司內(nèi)部地址發(fā)出來你們也訪問不了)文章里詳細(xì)的描述了問題發(fā)生的場景(和我上面描述的差不多)、問題定位過程還有解決方案。摘選文章上的解決方案：
明確了是線程安全的問題，解決方案就好確定了，解決線程安全有三種方案：
方案一：互斥同步——synchronized,ReentrantLock
方案二：非阻塞同步——CAS
方案三：無同步方案:——ThreadLocal
結(jié)合業(yè)務(wù)場景，綜合分析，最終確認(rèn)使用方案一，采用synchronized關(guān)鍵字，使用雙重檢查鎖的方式解決此問題。
大佬已經(jīng)將bug修復(fù)并發(fā)布了新版本到Maven倉庫，項目中有發(fā)生上述問題的，直接升級對應(yīng)的組件版本即可。既然官方已經(jīng)給出了解決方案，我直接升級項目中的組件版本號就行了。結(jié)果我一更換項目中的版本，我的項目就再也沒有啟動起來。研究發(fā)現(xiàn)，組件版本相差太多，很多依賴發(fā)生了沖突。我項目中使用的是 1.1.6-RELEASE ,問題官方在版本 2.1.0-RELEASE 中修復(fù)。這組件版本差距太大貿(mào)然升級肯定是有很大的風(fēng)險了，于是我放棄了!
另辟蹊徑解決
既然你自帶的插入方法有問題，我直接自定義一個插入方法不就得了。惹不起我還躲不起么!我最后又問了同事們最后都是怎么解決的，大家也都說是自定義SQL，而且都不再用框架自帶的方法了，大家都很聰明呀!(其實這個還有后續(xù)，后面有一期開發(fā)過程中，需要用到批量插入的功能，我又偷懶用了框架自帶的batch方法，又把我給坑了。從那之后，我再也沒有用自帶的方法了……)
問題2
我在排查上面的問題的時候，在框架里面看到了下面的代碼：
- private Number execute4PrimaryKey(String sqlId, Map<String, Object> paramMap, KeyHolder keyHolder) {
- long startTimestamp = System.currentTimeMillis();
- String sql = null;
- Object var8;
- try {
- MappedStatement mappedStatement = this.configuration.getMappedStatement(sqlId, true);
- mappedStmtThreadLocal.set(mappedStatement);
- sql = mappedStatement.getBoundSql(paramMap);
- int result = false;
- int result;
- if (keyHolder != null) {
- this.execution.update(sql, new MapSqlParameterSource(DalUtils.mapIfNull(paramMap)), keyHolder);
- result = keyHolder.getKey() == null ? 0 : keyHolder.getKey().intValue();
- } else {
- result = this.execution.update(sql, DalUtils.mapIfNull(paramMap));
- }
- Integer var9 = result;
- return var9;
- } catch (Exception var13) {
- this.throwException(var13);
- var8 = null;
- } finally {
- mappedStmtThreadLocal.remove();
- logger.debug("{} method:{}, sql:{}, param:{}", new Object[]{this.logPrefix, "execute", sql, paramMap});
- this.logProfileLongTimeRunningSql(startTimestamp, sql, paramMap);
- }
- return (Number)var8;
- }
大家仔細(xì)看看，這上面的代碼有個不容易發(fā)現(xiàn)的問題。問題是這樣的，我們系統(tǒng)中表的主鍵類型定義的都是 bigint ,這個類型對應(yīng)的是Java中的 Long 類型，說到這大家明白了么?對了，就是數(shù)據(jù)溢出的問題。
復(fù)現(xiàn)問題
我將表中的主鍵自增量設(shè)置為Java Int類型的最大值+1，也就是2147483648。然后數(shù)據(jù)庫再新增一條記錄，此時表中記錄的主鍵是2147483648，但Java實體中的主鍵ID已經(jīng)是個負(fù)數(shù)-2147483648了。
使用Long類型時，要注意JavaScript接收后端Long類型數(shù)據(jù)精度丟失問題
解決問題
這個問題還真不好另辟蹊徑了，只能后面出現(xiàn)類似的問題，升級ORM框架的版本了。
問題3
其實這個問題我應(yīng)該在看那篇內(nèi)部文章的時候就應(yīng)該發(fā)現(xiàn)的，但我當(dāng)時就是沒有看出來!此時的我留下了沒有技術(shù)的淚水。對于問題1，當(dāng)時那位大佬最終采用 synchronized 進(jìn)行加鎖解決多線程情況下共享變量讀寫問題，具體代碼如下(敏感信息打碼)：
修改前的代碼：
- public List<DalColumn> getDalColumnsWithoutId() {
- if (this.columnsWithoutId != null) {
- return this.columnsWithoutId;
- } else {
- this.columnsWithoutId = new ArrayList(this.dalColumns.size() - 1);
- Iterator var1 = this.dalColumns.iterator();
- while(var1.hasNext()) {
- DalColumn column = (DalColumn)var1.next();
- if (!column.isIdColumn()) {
- this.columnsWithoutId.add(column);
- }
- }
- return this.columnsWithoutId;
- }
- }
修改后的代碼(引用文章中的代碼截圖)：
問題復(fù)現(xiàn)
這個問題要復(fù)現(xiàn)的話，不太好復(fù)現(xiàn)，因為情況是比較極端的，但是在復(fù)雜的生產(chǎn)環(huán)境還是很可能出現(xiàn)的。
舉例說明：
假設(shè)有A、B兩個線程，A線程執(zhí)行到for循環(huán)處，B線程恰好執(zhí)行到最開始的if判斷處，由于此時的cloumnsWithId已經(jīng)被A線程賦值，肯定不為null，然后線程B就直接返回了，導(dǎo)致B線程調(diào)用者獲得了一個空的或者保存部分字段的cloumnsWithId。這種情況最終導(dǎo)致的結(jié)果是INSERT SQL中的字段缺失。
解決辦法
對于多線程下的共享變量，我們一定要堅持 讀讀可并行，讀寫要排隊 的原則。當(dāng)然能不加鎖的話，也是不錯的選擇。
我發(fā)現(xiàn)這個問題之后，就找到了前文中說的大佬，跟他反饋了我的想法，并提出我的解決方案。
- 直接在 getDalColumnsWithoutId 方法上添加 synchronized 。
- 修改第一個if判斷邏輯，然后使用 synchronized 鎖代碼塊。
- public List<DalColumn> getDalColumnsWithoutId() {
- int size = CollectionUtils.size(this.dalColumns);
- if (CollectionUtils.size(this.columnsWithoutId) == size && size > 0 ) {
- return this.columnsWithoutId;
- }
- synchronized(lock){
- if (columnsWithoutId == null) {
- columnsWithoutId = new ArrayList<>(size*2);
- }
- for (DalColumn column : this.dalColumns){
- if (!column.isIdColumn()) {
- this.columnsWithoutId.add(column);
- }
- }
- }
- return this.columnsWithoutId;
- }
當(dāng)時與大佬的溝通截圖，來自大佬的肯定：
總結(jié)
在遇到問題的時候不要著急，一定要學(xué)會大膽假設(shè)，然后小心求證。要勇敢地質(zhì)疑權(quán)威，不要認(rèn)為既然已經(jīng)是框架了就沒有bug。例如Spring從當(dāng)初的1.0到現(xiàn)在版本號都超過5.0了，除了給Spring增加新的功能，其他的升級就是在修復(fù)Spring中的bug。做出自己的假設(shè)之后，就要進(jìn)行場景復(fù)現(xiàn)，一個正常的bug是可以不斷地被復(fù)現(xiàn)的。復(fù)現(xiàn)了問題那就是找到問題的癥結(jié)所在，剩下的就是如何去解決啦!
