Oracle执行返回单个字段的SQL语句，效率低

flybalance commented 4 years ago

SmartSql version

4.1.41

Database provider and version

Oracle.ManagedDataAccess.Core 2.19.50

Steps to reproduce

执行类似于SELECT name FROM tableName WHERE id =:id这样，返回单个字段值的sql时，基本查询响应时间都在1000ms以上，速度比较慢，使用的是SmartSql.DyRepository模式。在DB中验证过执行速度，响应很快。

Expected result

Actual result

Stack trace

Ahoo-Wang commented 4 years ago

请贴执行代码。

flybalance commented 4 years ago

请贴执行代码。 sql语句 <Statement Id="FindSourceNameById"> SELECT name FROM dc_datasource WHERE id =:id </Statement>

namespace MarketAverage.Repository.Oracle { [SqlMap(Scope = "MappingDataIndexScope")] public interface IMappingDataIndexRepository { string FindSourceNameById(long id); } }

// 注册Oracle库实例 services.AddSmartSql(setup => { setup.UseAlias("Oracle"); setup.UseXmlConfig(smartSqlMapConfig: "Config\OracleSmartSqlMapConfig.xml"); }).AddRepositoryFromAssembly(options => { // SmartSql实例的别名 options.SmartSqlAlias = "Oracle"; // 仓储接口所在的程序集全称 options.AssemblyString = "MarketAverage.Repository.Oracle"; // Scope模板，默认是"I{Scope}Repository" //options.ScopeTemplate = "I{Scope}Repository"; });

ServiceProvider serviceProvider = services.BuildServiceProvider(); var mappingDataIndexRepository = serviceProvider.GetService(); var result = mappingDataIndexRepository.FindSourceNameById(6L);

Ahoo-Wang commented 4 years ago

SmartSql 日志贴一下。里边有明确记录哪个节点的耗时。

Ahoo-Wang commented 4 years ago

类似这样的。

flybalance commented 4 years ago

类似这样的。

2019-11-13T14:18:14.2757916+08:00 [DBG] Statement.Id:[CoreIndexExtendScope.FindIndexNameByCode],Sql: SELECT name FROM core_index WHERE code=@indexCode Parameters:[indexCode=IO_0000195572] Sql with parameter value: SELECT name FROM core_index WHERE code='IO_0000195572' (f371247e) 2019-11-13T14:18:14.2867923+08:00 [DBG] OpenConnection to MysqlDataCenter . (b0f85f74) 2019-11-13T14:18:14.4418011+08:00 [DBG] Operation:ExecuteScalar Statement.Id:CoreIndexExtendScope.FindIndexNameByCode Execute Taken:157. (bf214140) 2019-11-13T14:18:14.4428012+08:00 [DBG] Statement.Id:CoreIndexExtendScope.FindIndexNameByCode Invoke Taken:190. (55858869) 2019-11-13T14:18:14.4428012+08:00 [DBG] Dispose. (59883875) 2019-11-13T14:18:14.4768031+08:00 [DBG] Statement.Id:[MappingDataIndexScope.FindSourceNameById],Sql: SELECT name FROM dc_datasource WHERE id =:id Parameters:[id=6] Sql with parameter value: SELECT name FROM dc_datasource WHERE id =6 (2f11606f) 2019-11-13T14:18:14.4988044+08:00 [DBG] OpenConnection to OracleDataCenter . (5d8e1413) 2019-11-13T14:18:15.6448699+08:00 [DBG] Operation:ExecuteScalar Statement.Id:MappingDataIndexScope.FindSourceNameById Execute Taken:1167. (b928ea45) 2019-11-13T14:18:15.6448699+08:00 [DBG] Statement.Id:MappingDataIndexScope.FindSourceNameById Invoke Taken:1198. (bf9676af) 2019-11-13T14:18:15.6448699+08:00 [DBG] Dispose. (59883875) 2019-11-13T14:18:15.6548705+08:00 [DBG] Statement.Id:[MappingDataIndexScope.FindSourceNameById],Sql: SELECT name FROM dc_datasource WHERE id =:id Parameters:[id=12] Sql with parameter value: SELECT name FROM dc_datasource WHERE id =12 (94f69152) 2019-11-13T14:18:15.6568706+08:00 [DBG] OpenConnection to OracleDataCenter . (5d8e1413) 2019-11-13T14:18:15.6638710+08:00 [DBG] Operation:ExecuteScalar Statement.Id:MappingDataIndexScope.FindSourceNameById Execute Taken:9. (948dab2a) 2019-11-13T14:18:15.6638710+08:00 [DBG] Statement.Id:MappingDataIndexScope.FindSourceNameById Invoke Taken:9. (bc679fee) 2019-11-13T14:18:15.6638710+08:00 [DBG] Dispose. (59883875)

通过日志查看发现第一次加载的时候执行查询很耗时，之后的查询速度很快，但是通过执行日志发现了一个现象，跟MySql相比，MySql第一次的查询速度也很快，而Oracle却比较耗时，不知这是否是数据库驱动的问题

Ahoo-Wang commented 4 years ago

2019-11-13T14:18:14.4768031+08:00 [DBG] Statement.Id:[MappingDataIndexScope.FindSourceNameById],Sql:
SELECT name FROM dc_datasource WHERE id =:id
Parameters:[id=6]
Sql with parameter value:
SELECT name FROM dc_datasource WHERE id =6 (2f11606f)
2019-11-13T14:18:14.4988044+08:00 [DBG] OpenConnection to OracleDataCenter . (5d8e1413)
2019-11-13T14:18:15.6448699+08:00 [DBG] Operation:ExecuteScalar Statement.Id:MappingDataIndexScope.FindSourceNameById Execute Taken:1167. (b928ea45)
2019-11-13T14:18:15.6448699+08:00 [DBG] Statement.Id:MappingDataIndexScope.FindSourceNameById Invoke Taken:1198. (bf9676af)
2019-11-13T14:18:15.6448699+08:00 [DBG] Dispose. (59883875)

Operation:ExecuteScalar Execute Taken:1167. （ADO.NET 驱动执行耗时）
Invoke Taken:1198 （SmartSql 执行总耗时）

SmartSql 处理耗时 => 1198-1167 = 31.

另外我们在做性能测试的时候一般会执行预热，然后才会进入统计阶段。

Ahoo-Wang commented 4 years ago

还有就是如果开启日志，也会对性能产生不可忽略的影响。（我之前帮一位同学处理过类似事件，开启的DEBUG日志，输出到控制台，与不开启时场景性能相差几十倍甚至更多。）

flybalance commented 4 years ago

2019-11-13T14:18:14.4768031+08:00 [DBG] Statement.Id:[MappingDataIndexScope.FindSourceNameById],Sql:
SELECT name FROM dc_datasource WHERE id =:id
Parameters:[id=6]
Sql with parameter value:
SELECT name FROM dc_datasource WHERE id =6 (2f11606f)
2019-11-13T14:18:14.4988044+08:00 [DBG] OpenConnection to OracleDataCenter . (5d8e1413)
2019-11-13T14:18:15.6448699+08:00 [DBG] Operation:ExecuteScalar Statement.Id:MappingDataIndexScope.FindSourceNameById Execute Taken:1167. (b928ea45)
2019-11-13T14:18:15.6448699+08:00 [DBG] Statement.Id:MappingDataIndexScope.FindSourceNameById Invoke Taken:1198. (bf9676af)
2019-11-13T14:18:15.6448699+08:00 [DBG] Dispose. (59883875)

Operation:ExecuteScalar Execute Taken:1167. （ADO.NET 驱动执行耗时）
Invoke Taken:1198 （SmartSql 执行总耗时）

SmartSql 处理耗时 => 1198-1167 = 31.

另外我们在做性能测试的时候一般会执行预热，然后才会进入统计阶段。

好的，我再研究一下，谢谢解答。

dotnetcore / SmartSql