Job duration much longer than step durations

  • Ronzo

    Hall of Fame

    Points: 3741

    I have a particular VM instance of SQL that is exhibiting perplexing behavior. The job consists of two steps, the first typically runs in under 2 seconds, while the second runs around a minute. But the duration of the job itself has been ranging up to an hour! For example, the 11:37 run today list step 1 with a duration of 0:03, then shows step 2 with a 0:39 duration (but starting 5 minutes later), then shows a total duration of 7:02. The 11:47 run has durations of 0:00, 1:41 (starting 39 minutes later), and 40:55.

    Any ideas what to look for? I'm thinking the VM or SQL Agent is just overloaded, but was looking for input on both what would cause this behavior and how to best address it. Both job steps are simple invocations of stored procedures via TSQL.


    Have Fun!
    Ronzo

  • Alejandro Santana

    SSCommitted

    Points: 1667

    Hello

    Have you tried executing your procedures manually?

     

    Greetings

  • Grant Fritchey

    SSC Guru

    Points: 395394

    Sounds like blocking or resource contention. Take a look at the system_health Extended Event session. Excessive waits and blocks are automatically captured there. It should give you a lot more information to go on. Here's some examples of how to retrieve that data. You can also use the Data Viewer window to search them.

    ----------------------------------------------------
    The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood...
    Theodore Roosevelt

    The Scary DBA
    Author of: SQL Server 2017 Query Performance Tuning, 5th Edition and SQL Server Execution Plans, 3rd Edition
    Product Evangelist for Red Gate Software

  • Ronzo

    Hall of Fame

    Points: 3741

    Yes. Procedures run in indicated times (roughly 2 seconds and one minute) when run directly from query window. Only when run from job is there additional "delay".


    Have Fun!
    Ronzo

  • Ronzo

    Hall of Fame

    Points: 3741

    Grant,

    Thanks for suggestions. I will reply later with whatever I discover.


    Have Fun!
    Ronzo

  • Ronzo

    Hall of Fame

    Points: 3741

    Grant,

    Great references! I had to do a double take after reading your article and then finding my 4 health logs covered the last two seconds! I am diving deeper now, since it appears they are just full of (mostly) deadlocks writing to job history, which is firing trigger msdb.dbo.ti_Restart_Job.


    Have Fun!
    Ronzo

  • Ronzo

    Hall of Fame

    Points: 3741

    Yup, all our fault. The trigger ti_Restart_Job was added by the team to handle restarting jobs that are hung, but was not implemented very well. Thanks for help finding the issue.


    Have Fun!
    Ronzo

  • Grant Fritchey

    SSC Guru

    Points: 395394

    Thanks for coming back with what the problem was. So many people never let us know.

    You can modify system_health to keep more data, but, from the sounds of it, I wouldn't recommend that just yet. Best of luck.

    ----------------------------------------------------
    The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood...
    Theodore Roosevelt

    The Scary DBA
    Author of: SQL Server 2017 Query Performance Tuning, 5th Edition and SQL Server Execution Plans, 3rd Edition
    Product Evangelist for Red Gate Software

Viewing 8 posts - 1 through 8 (of 8 total)

You must be logged in to reply to this topic. Login to reply