really slow results that only appears to be happening with nodejs/tedious.

[webmandman]

UNIONS are super slow. Take this query example - it averages 120ms when i run this query directly in Azure Data Studio query runner, and when I use db drivers for lucee/coldfusion or .net c# web requests average 200ms which includes transforming to json for web responses.

i'm new to the nodejs server side, so that means I'm new to tedious as well.

If I remove the UNIONs, the query takes about 3 seconds, if I limit my subquery to 200 records its almost instant, but 3,000 to 4,000 records is what makes it 3 seconds.

If I don't modify this query it takes longer than 15 seconds, which timeouts.

select 
        r.total, r.lineitemcode, r.description, r.gcode, r.ocode, r.teamorg
    into #tmp1     
    from (
        select 
            total=sum(isnull(i.amount,0)),
            lineitemcode=a.GLGroup,
            a.[description],
            teamorg=i.org,
            gcode=(substring(i.org,7,2)),
            ocode=(SUBSTRING(org,10,2))
        from (
            select Account, Org, [Period], TransDate, Amount, rcode=(SUBSTRING(org,1,2)), tcode=(SUBSTRING(org,4,2)), gcode=(SUBSTRING(org,7,2)), ocode=(SUBSTRING(org,10,2)) 
            from LedgerAP where [period] between 202301 and 202302 and SkipGL = 'N'
            union all 
            select Account, Org, [Period], TransDate, Amount, rcode=(SUBSTRING(org,1,2)), tcode=(SUBSTRING(org,4,2)), gcode=(SUBSTRING(org,7,2)), ocode=(SUBSTRING(org,10,2)) 
            from LedgerAR where [period] between 202301 and 202302 and SkipGL = 'N'
            union all 
            select Account, Org, [Period], TransDate, Amount, rcode=(SUBSTRING(org,1,2)), tcode=(SUBSTRING(org,4,2)), gcode=(SUBSTRING(org,7,2)), ocode=(SUBSTRING(org,10,2)) 
            from LedgerMisc where [period] between 202301 and 202302 and SkipGL = 'N'
            union all 
            select Account, Org, [Period], TransDate, Amount, rcode=(SUBSTRING(org,1,2)), tcode=(SUBSTRING(org,4,2)), gcode=(SUBSTRING(org,7,2)), ocode=(SUBSTRING(org,10,2)) 
            from LedgerEx where [period] between 202301 and 202302 and SkipGL = 'N'
        ) i
            left join (
                select l.GLGroup, l.[Description], l.StartAccount, l.EndAccount, c.Account, c.Name
                from (
                    select glgroup, [Description], StartAccount, EndAccount
                    from GLGroupDetail gd
                        left join GLGroup g on g.code = gd.GLGroup
                    where gd.TableNo = 20 
                ) l
                join ca c on c.Account >= l.StartAccount and c.Account <= l.EndAccount
            ) a on a.Account = i.account 
        group by a.GLGroup, a.[Description],i.org
    ) r 

    delete from #tmp1 where gcode = 'IN'

    update #tmp1 set gcode = 'OH' where ocode in ('3L','3I','3J','3M') or gcode = 'IN'

    select 
        total=sum(isnull(x.total,0)),
        x.lineitemcode,
        x.[Description],
        x.gcode,
        groupname=(select ocd.label from cfgorgcodesdescriptions ocd where ocd.code=x.gcode and ocd.orglevel = 3)
    from 
        #tmp1 x
    where x.gcode <> '00' and x.gcode <> '20'
    group by x.lineitemcode, x.description, x.gcode

    drop table #tmp1

Expected behaviour:

I expect almost instant query results.

Actual behaviour:

Its too slow. times out after 15 seconds

Configuration:

const sqlConfig = {
        user: process.env.db_user,
        password: process.env.db_password,
        database: process.env.db_database_vision,
        server: process.env.db_host,
        pool: {
          max: 10,
          min: 0,
          idleTimeoutMillis: 30000
        },
        options: {
          encrypt: true, // for azure
          trustServerCertificate: true // change to true for local dev / self-signed certs
        }
      }

Software versions

• NodeJS: 16.15.1
• node-mssql: 9.3.1
• SQL Server: Microsoft SQL Server 2016 (SP1-GDR) (KB4505219) - 13.0.4259.0 (X64) Jun 15 2019 19:20:12 Copyright (c) Microsoft Corporation Standard Edition (64-bit) on Windows Server 2016 Standard 6.3 (Build 14393: ) (Hypervisor)

[dhensby]

The first thing to do is to determine where the time is being taken.

If you enable the debug output by setting the environment DEBUG environment variable to DEBUG=* then you'll see all debugging info in the console (which will be a bit overwhelming), but it should let you get a feel for where the request is hanging.

Generally, for large result sets you want to be using a stream to process the rows in chunks rather than loading thousands of rows into memory at once as that will be slow and you're also blocking your application from being able to manipulate the data until it's all been loaded.

[webmandman]

thanks for that.

It appears that mssql:base connection takes too long to be "released".

mssql:base pool(1): created +0ms
mssql:base pool(1): connecting +1ms
mssql:tedi pool(1): connection #1 created +0ms
mssql:tedi connection(1): establishing +0ms
mssql:tedi connection(1): established +227ms
mssql:base pool(1): connected +229ms
mssql:tedi connection(1): destroying +1ms
mssql:tedi connection(1): destroyed +1ms
mssql:base request(1): created +0ms
mssql:tedi pool(1): connection #2 created +3ms
mssql:tedi connection(2): establishing +0ms
mssql:tedi connection(2): established +196ms
mssql:tedi connection(2): borrowed to request #1 +0ms
mssql:tedi request(1): query 
    select
        r.total, r.lineitemcode, r.description, r.gcode, r.ocode, r.teamorg
    ...
    drop table #tmp1 +0ms
mssql:base connection(2): released +15s
mssql:tedi request(1): failed RequestError: Timeout: Request failed to complete in 15000ms

What does this output say about my query or code? this query uses GROUP BY and the resultset will never be more than 378 records, which is not much.

if I run this query here which results in 18,000+ records its actually faster

select Account, Org, [Period], TransDate, Amount, rcode=(SUBSTRING(org,1,2)), tcode=(SUBSTRING(org,4,2)), gcode=(SUBSTRING(org,7,2)), ocode=(SUBSTRING(org,10,2)) 
            from LedgerAP where [period] between 202301 and 202302 and SkipGL = 'N'

[dhensby]

Ok - that's not quite giving enough information - it's just telling us that the query didn't complete in the 15 seconds (which we kind of knew) - I was hoping to get some internals from tedious there, but we aren't.

If you pass the debug option to the pool config:

const sqlConfig = {
        user: process.env.db_user,
        password: process.env.db_password,
        database: process.env.db_database_vision,
        server: process.env.db_host,
+        debug: true,
        pool: {
          max: 10,
          min: 0,
          idleTimeoutMillis: 30000
        },
        options: {
          encrypt: true, // for azure
          trustServerCertificate: true // change to true for local dev / self-signed certs
        }
      }

and then add a listener to the pool for the debug event:

const { ConnectionPool } = require('mysql');
const debug = require('debug')('mssql:custom');

function getDbPool() {
  const pool = new ConnectionPool(sqlConfig);
  pool.on('debug', (msg) => debug(msg));
  return pool.connect();
}

Then you should see a log more debugging coming out. It won't have the pool/connection IDs, but if you only have one query running, that's not a problem.

[webmandman]

I got the debug output for this, but its a lot and the terminal runs out of space. in this nextjs app I do not know how to output to a file...I did try a couple ways but could not get it working.

[webmandman]

mssql-debug.log here is what I could copy from the terminal output.

[webmandman]

@dhensby Nevermind dude! The query was being run in an environment that does not use table indexes.

My .env.local variables for nextjs app was configured to use the correct environment, BUT I did not know that I had to kill the terminal to reload the environment variables. Simply restarting the nextjs app does not reload env vars.

Sorry to bother. Tedious is good!

[dhensby]

Glad you got to the bottom of it!