DLYJOB DLY(1) takes +3600 seconds to complete

[soup_dog]

Ok, here is a weird one. I have a CLP that is using a timestamp to build a file name for FTP. To prevent duplicate filenames, I have a delay of one second in the CLP. This morning I noticed a user's job being stuck on the delay process for much longer than 1 second. One example took 1 hour and 20 minutes! Amazingly, none of the users have mentioned this issue and no error messages are showing up in the job log. Has anyone ever had this problem or have any ideas what may be happening?

Here is the CLP snippet.

0078.18              DLYJOB     DLY(1)                                          
0078.19              DLCOBJ     OBJ((DMMFTPLOCK *DTAARA *EXCL))                 
0078.20              MONMSG     MSGID(CPF0000 MCH0000)                          
0078.21

Looking at the job log, everything looks fine.

   7700 - CALL PGM(DMMPUT)          /* The CALL command contains parame
   */                                                                  
   7818 - DLYJOB DLY(1)                                                
   7819 - DLCOBJ OBJ((DMMFTPLOCK *DTAARA *EXCL))                       
   9600 - FTP RMTSYS('XX.XXX.XXX.XXX')

But check out the time stamps on those messages in the job log!

                                                                               
From . . . . . . . . . :   XXXXXX                                             
Date sent  . . . . . . :   02/17/09      Time sent  . . . . . . :   7:17:59   
                                                                               
Message . . . . :     7818 - DLYJOB DLY(1)

From . . . . . . . . . :   XXXXXXXX                                           
Date sent  . . . . . . :   02/17/09      Time sent  . . . . . . :   08:39:01 
                                                                             
Message . . . . :     7819 - DLCOBJ OBJ((DMMFTPLOCK *DTAARA *EXCL))

I really hope someone has seen something like this before.

Thanks in advance, Soup.

[Mercury]

Re: DLYJOB DLY(1) takes +3600 seconds to complete

Could that have something to do with the timestamp on job log ? That is, no job stuck, everything went well but the time on job log is corrupted for an unknown reason. That should be why your users have nothing to mention since it is not an issue for them.

[soup_dog]

Re: DLYJOB DLY(1) takes +3600 seconds to complete

yeah, I was thinking that too. But I watched one users job and it sat on that command for at least ten minutes. (Granted, the job may have been chugging along just fine and the job log just wasn't getting updated, but that would suck too. LOL) I have a call in to the user to see if they have experienced these delays, but I haven't heard back yet.

[MichaelCatalani]

Re: DLYJOB DLY(1) takes +3600 seconds to complete

When you say the job was stuck on the delay process, was the job in DLYW status?

If not, then it wasn't stuck on the DelayJob command. In that case, it may have been stuck on the DLCOBJ command. This could be caused because the lock couldnt be lifted, and someone has changed the default wait time for the job to something really high. To rule this out, display the jobs wait time the next time one is running to see what it is set to. The default is 30 seconds.

[soup_dog]

Re: DLYJOB DLY(1) takes +3600 seconds to complete

Ok, that makes sense. But since the only way to reach this point in the program is to have allocated the object that is being deallocated, what would cause a delay in the deallocation? Shouldn't that be almost an immediate kind of thing?

[soup_dog]

Re: DLYJOB DLY(1) takes +3600 seconds to complete

Ok, I managed to catch one in action. Here is a look at the job via WRKACTJOB.

   QPADEV006R   XXXXXXX     INT      .0  DLY-1            DSPW        
   QPADEV006T   XXXXXXXXXX  INT      .0  PGM-IQINTPGM     DSPW        
   QPADEV006V   XXXXXXX     INT      .0  PGM-OEINTPGM     DSPW        
   QPADEV0060   XXXXXX      INT      .0  PGM-MFGINTPGM    DSPW

So I guess you are saying it's not really in the dlyjob statement because the status isn't DLYW. The last statement showing in the job log is the DLYJOB command and the default wait on the job is 30 seconds.

[soup_dog]

Re: DLYJOB DLY(1) takes +3600 seconds to complete

Ok, I just got confirmation from the user. She is not getting locked up at all. So now that begs the question... what the hell is going on with the timestamps in my job log? I am not getting warm fuzzies here.

[Mercury]

Re: DLYJOB DLY(1) takes +3600 seconds to complete

Missing PTF ? Just a guess...

[MichaelCatalani]

Re: DLYJOB DLY(1) takes +3600 seconds to complete

Maybe your machine is tired and lazy today.

Besides a ptf issue, thats all I have. I dont know of a logging setting that says "log the event whenever you feel like it", which appears to be what its doing.

[soup_dog]

Re: DLYJOB DLY(1) takes +3600 seconds to complete

Maybe your machine is tired and lazy today.

Besides a ptf issue, thats all I have. I dont know of a logging setting that says "log the event whenever you feel like it", which appears to be what its doing.

LOL! Yeah, this is pretty bizarre.

[Mercury]

Re: DLYJOB DLY(1) takes +3600 seconds to complete

If I am not mistaken I am under the strong impression that this issue has something to do with DLCOBJ, not DLYJOB.
Can you show where the related ALCOBJ is ? Is it in the same CL ?

[kuempi]

Re: DLYJOB DLY(1) takes +3600 seconds to complete

If I am not mistaken I am under the strong impression that this issue has something to do with DLCOBJ, not DLYJOB.
Can you show where the related ALCOBJ is ? Is it in the same CL ?

I think thats the point!

try to do something like this:

00xx.xx               SNDPGMMSG MSG(TIMESTAMP) TOMSGQ(*HSTLOG)
0078.18              DLYJOB     DLY(1)                                          
00xx.xx               SNDPGMMSG MSG(TIMESTAMP) TOMSGQ(*HSTLOG)
0078.19              DLCOBJ     OBJ((DMMFTPLOCK *DTAARA *EXCL))                 
0078.20              MONMSG     MSGID(CPF0000 MCH0000) 

kuempi

[MichaelCatalani]

Re: DLYJOB DLY(1) takes +3600 seconds to complete

If the job is hung on the DLCOBJ command, it shouldnt be in DSPW status. Since the users arent reporting getting hung up, then the DLCOBJ is probably executing quickly. If it were not, then not only would this user be hung up, but anyone else who attempted to use this data area would also hang, and that doesn't appear to be happening.


I am assuming that the cl commands are getting logged by setting the LOGCLPGM parameter on the job to "Y". If they are getting logged by some sort of fancy smancy program / api, then that program could be a problem.

[soup_dog]

Re: DLYJOB DLY(1) takes +3600 seconds to complete

Correct. The users are not getting delayed, so the DLCOBJ cannot be holding things up. In fact the user was very surprised when I asked her about any delays. Here is the code, including the allocate.

    ALCOBJ     OBJ((DMMFTPLOCK *DTAARA *EXCL)) WAIT(2)      
    MONMSG     MSGID(CPF0000 MCH0000)                       
                                                            
CALL       PGM(DMMPUT) PARM(&SRCFILE &SRCLIB &NEWFILE)    

            DLYJOB     DLY(1)                                         
            DLCOBJ     OBJ((DMMFTPLOCK *DTAARA *EXCL))                
            MONMSG     MSGID(CPF0000 MCH0000)

The call to DMMPUT runs in less than a second which is the reason why I needed to put the dlyjob in there.

And yes, the logclpgm parameter is set to a 'Y' in this case.

I'm baffled.

[Mercury]

Re: DLYJOB DLY(1) takes +3600 seconds to complete

The call to DMMPUT runs in less than a second which is the reason why I needed to put the dlyjob in there.

So what ? Even if the run takes less than 1 second I do not see why you need this delay ?