最近写一个东西在用一个数据库中间件对go(xorm)中操作sql时出现一个异常:
[mysql] 2021/01/01 15:13:49 packets.go:467: busy buffer
panic: commands out of sync. Did you run multiple statements at once?
最开始各种搜索,也分析源码以为是buffer太小的原因,增大buffer后依然无法解决,后来分析相关日志发现,github.com/go-sql-driver/mysql 这个包对于查询
Mysqldb.Where("openid=?","具体值").Get(finduser)
的处理使用了预处理 SQL方式,通过查询执行sql日志发现上一个查询的后台执行时:
2021-01-01T07:10:17.192950Z 40 Connect remote@127.0.0.1 on mydb using TCP/IP
2021-01-01T07:10:17.196651Z 40 Query SET NAMES utf8
2021-01-01T07:10:17.198839Z 40 Prepare SELECT `openid`, `unionid`, `deleted_at`, `created_at`, `updated_at`, `id` FROM `tslog` WHERE (openid=?) LIMIT 1
2021-01-01T07:10:17.200948Z 40 Execute SELECT `openid`, `unionid`, `deleted_at`, `created_at`, `updated_at`, `id` FROM `tslog` WHERE (openid='具体值') LIMIT 1
2021-01-01T07:10:17.204922Z 40 Close stmt
所以此时异常卡在了中间件对语句对预处理sql执行后返回的处理。
原因找到本该到此为止,但想到php框架中对于执行一个sql的具体流程时什么样的,索性就查下,下面分别对laravel8的DB,Eloquent和简单的medoo的执行处理过程:
2021-01-01T07:08:41.414498Z 39 Connect remote@127.0.0.1 on mydb using TCP/IP
2021-01-01T07:08:41.418254Z 39 Query use `mydb`
2021-01-01T07:08:41.424227Z 39 Prepare set names 'utf8mb4' collate 'utf8mb4_unicode_ci'
2021-01-01T07:08:41.427114Z 39 Execute set names 'utf8mb4' collate 'utf8mb4_unicode_ci'
2021-01-01T07:08:41.430617Z 39 Close stmt
2021-01-01T07:08:41.430749Z 39 Prepare set session sql_mode='ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION'
2021-01-01T07:08:41.435796Z 39 Execute set session sql_mode='ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION'
2021-01-01T07:08:41.441323Z 39 Close stmt
2021-01-01T07:08:41.441734Z 39 Prepare select * from tslog where openid='具体值'
2021-01-01T07:08:41.445707Z 39 Execute select * from tslog where openid='具体值'
2021-01-01T07:08:41.449343Z 39 Close stmt
2021-01-01T07:08:41.455379Z 39 Quit
2021-01-01T07:07:09.201554Z 38 Connect remote@127.0.0.1 on mydb using TCP/IP
2021-01-01T07:07:09.216170Z 38 Query use `mydb`
2021-01-01T07:07:09.219893Z 38 Prepare set names 'utf8mb4' collate 'utf8mb4_unicode_ci'
2021-01-01T07:07:09.224192Z 38 Execute set names 'utf8mb4' collate 'utf8mb4_unicode_ci'
2021-01-01T07:07:09.227458Z 38 Close stmt
2021-01-01T07:07:09.227612Z 38 Prepare set session sql_mode='ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION'
2021-01-01T07:07:09.230597Z 38 Execute set session sql_mode='ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION'
2021-01-01T07:07:09.235626Z 38 Close stmt
2021-01-01T07:07:09.236180Z 38 Prepare select * from `tslog` where `openid` = ? and `tslog`.`id` = ? limit 1
2021-01-01T07:07:09.238363Z 38 Prepare select * from `tslog` where `openid` = ? and `tslog`.`id` = ? limit 1
2021-01-01T07:07:09.238401Z 38 Execute select * from `tslog` where `openid` = '具体值' and `tslog`.`id` = 1 limit 1
2021-01-01T07:07:09.241515Z 38 Close stmt
2021-01-01T07:07:09.246249Z 38 Quit
2021-01-01T07:11:59.492672Z 41 Connect remote@127.0.0.1 on mydb using TCP/IP
2021-01-01T07:11:59.495868Z 41 Query SET SQL_MODE=ANSI_QUOTES
2021-01-01T07:11:59.497787Z 41 Query SET NAMES 'utf8'
2021-01-01T07:11:59.504909Z 41 Query SELECT "unionid","id" FROM "tslog" WHERE "openid" = '具体值' LIMIT 1
2021-01-01T07:11:59.517974Z 41 Quit
由此可见在laravel中对于一条简单sql的处理都会执行执行一系列的sql设置最后查询,并且设置和查询都以预处理方式进行。虽说预处理在一定程度上是优化同一sql频繁查询,但我执行并列执行同一sql,在输出的sql日志:
/执行:
Wxlogin::where(“openid”,”具体值”)->find(1);
Wxlogin::where(“openid”,”具体值”)->find(1);
两次
日志省略前后sql/
2021-01-01T08:09:39.671826Z 48 Prepare select * from `tslog` where `openid` = ? and `tslog`.`id` = ? limit 1
2021-01-01T08:09:39.674598Z 48 Prepare select * from `tslog` where `openid` = ? and `tslog`.`id` = ? limit 1
2021-01-01T08:09:39.674635Z 48 Execute select * from `tslog` where `openid` = '具体值' and `tslog`.`id` = 1 limit 1
2021-01-01T08:09:39.678185Z 48 Close stmt
2021-01-01T08:09:39.680208Z 48 Prepare select * from `tslog` where `openid` = ? and `tslog`.`id` = ? limit 1
2021-01-01T08:09:39.682838Z 48 Prepare select * from `tslog` where `openid` = ? and `tslog`.`id` = ? limit 1
2021-01-01T08:09:39.682871Z 48 Execute select * from `tslog` where `openid` = '具体值' and `tslog`.`id` = 1 limit 1
2021-01-01T08:09:39.686475Z 48 Close stmt
可见每条都执行一次预处理,并未使用其优化方式。又一方面预处理在一定程度上预防sql注入,但在开始配置处的预处理应该可以忽略。
而Medoo这个简单的数据库框架对于相关配置不是太复杂,但对于查询语句执行时未进行预处理,虽然框架中说明有一些安全的方法处理,但若是自己定义相关优化或者防注入也可以在这里注意。
另对于中间件需要针对使用语言和框架进行相关调整,不然通常正常的sql执行可能出现莫名的异常。