Re: BLCR: sleep process checkpointing problem

From: Paul H. Hargrove (PHHargrove_at_lbl_dot_gov)
Date: Thu Mar 18 2010 - 13:48:52 PDT

  • Next message: Paul H. Hargrove: "Re: BLCR: sleep process checkpointing problem"
    Zsombor,
    
    Thanks for the explanation.  I now understand what it is you are asking 
    about, though I am not certain I have a satisfactory answer.  I am not 
    aware of any specific reason why the sleep is resuming from the initial 
    30sec time.  However, I did try some experiments with strace of "sleep 
    30" (passing --ptraced-allow to cr_checkpoint and NOT including the 
    strace in the checkpoint)
    
    Sending SIGTSTP, the relevant part of the strace output shows:
    
    > $ strace /bin/sleep 30
    > [...]
    > nanosleep({30, 0}, [*] 0)                   = ? ERESTART_RESTARTBLOCK 
    > (To be restarted)
    > --- SIGTSTP (Stopped) @ 0 (0) ---
    > --- SIGTSTP (Stopped) @ 0 (0) ---
    > restart_syscall(<... resuming interrupted call ...>) = 0
    > close(1)                                = 0
    > close(2)                                = 0
    > exit_group(0)                           = ?
    
    Where the "[...]" is output I removed and "[*]" is my addition to mark 
    the point where the output paused until the signal was sent.
    It is interesting to note that I did NOT send the SIGCONT in this case - 
    the sleep program apparently is able to keep running due to some 
    multi-threaded tricks (note there are TWO "SIGTSTP" lines indicating the 
    signal was delivered to 2 tasks).  Surprising to me is the fact that 
    sleep is apparently able to run through receiving the unblockable 
    SIGSTOP signal as well!
    
    Now, if I try to checkpoint instead of signal:
    >
    > $ strace cr_run /bin/sleep 30
    > [...]
    > nanosleep({30, 0}, [*] 0)                   = ? ERESTART_RESTARTBLOCK 
    > (To be restarted)
    > --- SIGRT_32 (Real-time signal 30) @ 0 (0) ---
    > ioctl(3, 0x4008a101, 0x4000)            = 0
    > rt_sigreturn(0x7fc9671a8530)            = -1 EINTR (Interrupted system 
    > call)
    > nanosleep({30, 0}, NULL)                = 0
    > close(1)                                = 0
    > close(2)                                = 0
    > exit_group(0)                           = ?
    
    The ERESTART_RESTARTBLOCK/restart_syscall is some kernel "magic" to 
    automatically/transparently restart certain interrupted system calls 
    with DIFFERENT arguments than were passed originally.  In the case of 
    nanosleep this is used to restart the call with the time adjusted to 
    exclude the time already spent in the call.  It looks as if that is lost 
    in the checkpoint case, and rather than the transparent restart of the 
    nanosleep system call one sees a return of -1 with errno=EINTR.  The 
    second argument to the nanosleep() is where the kernel would normally be 
    able to write the remaining time when interrupted, but the caller has 
    passed NULL which means it has no such information is available and 
    apparently chooses restart the system call with the original arguments.
    
    I am not sure what the interaction is between the checkpoint and the 
    system call restart logic, but my first and second guesses would be:
    1) Perhaps the fact that libcr installs a handler for our signal 
    (SIGRT_32) tells the kernel not to transparently restart the call.
    2) Perhaps the existence of a handler is OK, but the presence of a 
    system call (ioctl in this case) in the handler prevents the restart.
    
    I think the first guess is more likely, but hope to learn more by 
    looking at the kernel code in more detail.
    I either case, I suspect that one could implement a replacement for 
    /bin/sleep that has the proper behavior in the presence of EINTR. 
    
    For what it is worth, sleep() in perl apparently does NOT restart on 
    EINTR.  So, as an ugly work-around you might replace /bin/sleep with 
    "perl -e sleep".
    
    It would be helpful to me if you could enter some of this information in 
    our bug database (you could just paste this email into the bug report if 
    you wish)
       https://upc-bugs.lbl.gov/bugzilla
    That will make it less likely that I will loose track of this issue.
    
    -Paul
    
    Zsombor Nagy wrote:
    > Hi Paul!
    >
    > I'm working with Iván and Gábor on this project, and I found this sleep issue interesting, so I played a bit with it today. Here I'm going to summarize what is our problem.
    >
    > Sorry for the long mail!
    >
    >
    >
    > I've made a sleeper script, which looks like this:
    >
    > $ cat sleeper.sh 
    > #!/bin/bash
    > echo Starting: `date +%H:%M:%S`
    > sleep 30
    > echo Ending: `date +%H:%M:%S`
    >
    >
    > Signalling
    > ------------
    >
    > I'm executing it:
    >
    > $ ./sleeper.sh 
    > Starting: 13:49:13
    > Ending: 13:49:43
    >
    > Then with cr_run:
    >
    > $ cr_run ./sleeper.sh 
    > Starting: 13:49:56
    > Ending: 13:50:26
    >
    > No surprises: 30 seconds.
    >
    >
    > Now I have an other script, called 'signaller':
    >
    > $ cat signaller.sh 
    > #!/bin/bash
    > PID=`pgrep sleeper`
    > echo Sending TSTP signal to PID $PID at `date +%H:%M:%S`
    > kill -TSTP $PID
    > echo Waiting for 5 sec.
    > sleep 5
    > echo Sending CONT signal to PID $PID at `date +%H:%M:%S`
    > kill -CONT $PID
    >
    > This one sends a TSTP signal to our sleeper process, then waits for 5 seconds, then sends a continue signal.
    >
    > Now I start the sleeper script, and then after 5 seconds, I start the signaller script in a second terminal window, but I will mix to output here to make it easier to follow:
    >
    > - sleeper:
    >
    > Starting: 13:52:17
    >
    > - signaller:
    >
    > Sending TSTP signal to PID 6069 at 13:52:22
    > Waiting for 5 sec.
    > Sending CONT signal to PID 6069 at 13:52:27
    >
    > - back to sleeper:
    >
    > Ending: 13:52:47
    >
    >
    > As you can see, the sleeper run for exactly 30 seconds no matter we stopped it for 5 seconds.
    > The reason for this is the behaviour of the sleep: it just checks the time of the start, and if the current time minus the start time is more then the number of seconds it needs to sleep, it is done. So it does not matter that for 5 seconds it was not running, after the current time reaches the start time + 30 seconds, it will quit - unless it is stil stopped. So if I run the signaller just slightly before the 30 seconds are up:
    >
    > - sleeper:
    >
    > Starting: 13:56:24
    >
    > - signaller:
    >
    > Sending TSTP signal to PID 7629 at 13:56:53
    > Waiting for 5 sec.
    > Sending CONT signal to PID 7629 at 13:56:58
    >
    > - back to sleeper:
    >
    > Ending: 13:56:58
    >
    >
    > As you can see, the sleeper run for 34 seconds, because we sent the CONT signal at 13:56:58, and then the sleeper process continued to run, realized that the time is up, and quited immediately. 
    >
    >
    > So I think this behaviour is understandable and OK, there is no more question related to this, this is just the way sleep works.
    >
    >
    >
    > Checkpointing
    > ------------------
    >
    > I have a third script, called 'checkpointer':
    >
    > $ cat checkpointer.sh 
    > #!/bin/bash
    > PID=`pgrep sleeper`
    > echo Checkpointing PID $PID at `date +%H:%M:%S`
    > cr_checkpoint $PID
    >
    > it just prints the time and then call cr_checkpoint.
    >
    >
    > Let's run the sleeper, and then after a few seconds, run the checkpointer:
    >
    > - sleeper:
    >
    > Starting: 14:03:23
    >
    > - checkpointer:
    >
    > Checkpointing PID 10237 at 14:03:27
    >
    > - back to sleeper:
    >
    > Ending: 14:03:57
    >
    > The sleeper process started at 23 and finished at 57 which is 34 seconds. But the interesting part is that we created the checkpoint at 27, and the sleeper finished at 57, which is exactly 30 sec. It looks like as the sleep would be restarted by the checkpointing.
    >
    > Another try:
    >
    > - sleeper:
    >
    > Starting: 14:05:48
    >
    > - checkpointer:
    >
    > Checkpointing PID 11118 at 14:06:04
    >
    > - back to sleeper:
    >
    > Ending: 14:06:34
    >
    >
    >
    > The sleeper started at 5:48, finished at 6:34, which is 48 seconds - we checkpointed at 6:04, and the sleeper ended at 6:34, which is 30 seconds - again, looks like the checkpoint command restarts the sleep!
    >
    > That's the behaviour we try to understand, and hopefully avoid.
    >
    > The worst case scenario could be: having a periodical checkpointing every 20 seconds would restart the 'sleep 30' every time, which would mean it would never finish.
    >
    >
    > I hope it's clearer now what we try to figure out.
    >
    > Looking forward to your answer!
    >
    > Thank you very much!
    >
    > Cheers,
    > Zsombor Nagy
    >
    >
    >
    > On 2010.03.17., at 23:50, Paul H. Hargrove wrote:
    >
    >   
    >> I am sorry, but I am not clear what it is you now need my help to explain.
    >>
    >> If have shown, and you have reproduced, a mechanism by which /usr/bin/sleep can be made to delay for an unexpectedly long period of time.  This is true regardless of whether BLCR is present or absent on the system.  If you are hoping that I know why this "extra"  sleep time occurs, then I am afraid I have no idea.
    >>
    >> If, however, you are asking about some behavior when using BLCR the "restart" a checkpointed /usr/bin/sleep process, then please re-ask the question clearly and I'll try to help.
    >>
    >> -Paul
    >>
    >> Ivan Marton wrote:
    >>     
    >>> Dear Paul!
    >>>
    >>> Sorry for the late answer! We have executed your suggested test and experienced the same. After a deeper examination we have found that this behavior can be very easily explained with the surprisingly implementation of the sleep program.
    >>>
    >>> It simply stores the time when started and check very often periodically whether the given period has passed or not. (Or at least in that time when it's running.) When you have suspended it this "counter" didn't stop and immediately returned when the process was continued.
    >>>
    >>> The restart of this "counter" seems to be a completely different problem. Could you help to locate the problem or explain if its a feature?
    >>>
    >>> Thank you!
    >>>
    >>> Cheers,
    >>> Ivan Marton
    >>>
    >>> On Mar 11, 2010, at 5:53 PM, Paul H. Hargrove wrote:
    >>>
    >>>       
    >>>> Gábor,
    >>>>
    >>>> To help determine if this is a BLCR-specific problem, or a signal-handling issue in your /bin/sleep (or kernel), please try
    >>>> $ kill -TSTP <PID> ; sleep 15; kill -CONT <PID>
    >>>> instead of running
    >>>> $ cr_checkpoint <PID>
    >>>> and report the running time for the sleep command.
    >>>> You could also repeat this TSTP/CONT experiment running /bin/sleep without cr_run.
    >>>>
    >>>> At least for me (CentOS 5.4 w/ 2.6.18-164.11.1.el5 kernel), I find that the TSTP/CONT experiment causes "time /bin/sleep" to report "extra" time without any involvement from BLCR.  Here is an example w/ "/bin/sleep 30" and a "sleep 35" between the two signals.  Strangely, I get 55s (which is not 30+35):
    >>>>         
    >>>>> $ time /bin/sleep 30 &
    >>>>> [1] 3538
    >>>>> $ ps aux|grep sleep
    >>>>> phargrov  3539  0.0  0.1  58920   516 pts/0    S    13:07   0:00 /bin/sleep 30
    >>>>> phargrov  3541  0.0  0.1  61180   736 pts/0    S+   13:07   0:00 grep sleep
    >>>>> $ kill -TSTP 3539
    >>>>> $ sleep 35; kill -CONT 3539
    >>>>> $
    >>>>> real    0m55.538s
    >>>>> user    0m0.000s
    >>>>> sys     0m0.002s
    >>>>>           
    >>>> -Paul
    >>>>
    >>>> Gábor Rőczei wrote:
    >>>>         
    >>>>> Dear BLCR developers,
    >>>>>
    >>>>> I am working for a company in Hungary, its name is NIIF (http://www.niif.hu/en). Our one main area is the grid computing and we have a country size grid infrastructure.  The PCs are provided by participating Hungarian institutes, such as high schools, universities, or public libraries.  Every contributor uses their PCs for their own purposes during the official work hours, such as educational or office-like purposes, and offers the infrastructure for high-throughput computation whenever they do not use them for any other purposes, i.e. during the nights and the unoccupied week-ends. The combined use of "day-shift" (i.e. individual mode) and "night-shift" (i.e. grid mode) enables us to utilize CPU cycles (which would have been lost anyway) to provide firm comutational infrastructure to the national research community (more information about our grid: http://www.clustergrid.hu/). The PCs are running Linux at "grid mode" and they are using Windows at "daytime mode". When !
     t!
    >>>>>           
    >  he PC switch from  Linux to Windows then the jobs are chechpointed and when they change from Windows to Linux then the jobs will be restarted. This is why we need checkpointing.
    >   
    >>>>> The current state we are using Condor and its checkpointing library but there was some problems with it and we decided that we will change them to Sun Grid Engine and BLCR soon. I read that Sun Grid Engine can configured with BLCR:
    >>>>>
    >>>>> http://gridengine.sunsource.net/project/gridengine/howto/howto.html
    >>>>>
    >>>>> Section: Checkpointing under Linux with Berkeley Lab Checkpoint/Restart
    >>>>>
    >>>>> http://gridengine.sunsource.net/project/gridengine/howto/APSTC-TB-2004-005.pdf 
    >>>>>
    >>>>> We found a sleep problem. Here is the description:
    >>>>>
    >>>>> If I am not checkpointing  the sleep process:
    >>>>>
    >>>>> roczei@knowarc2:~$ time cr_run /bin/sleep 10
    >>>>>
    >>>>> real    0m10.126s
    >>>>> user    0m0.004s
    >>>>> sys    0m0.012s
    >>>>>
    >>>>> If I am  checkpointing the sleep process:
    >>>>>
    >>>>> roczei@knowarc2:~$ time cr_run /bin/sleep 10
    >>>>>
    >>>>> real    0m20.404s
    >>>>> user    0m0.008s
    >>>>> sys    0m0.008s
    >>>>> roczei@knowarc2:~$
    >>>>>
    >>>>> Other terminal:
    >>>>>
    >>>>> roczei@knowarc2:~$ ps aux | grep sleep
    >>>>> roczei   17113  2.6  0.3   3048   544 pts/0    S+   09:39   0:00 /bin/sleep 10
    >>>>> roczei   17115  0.0  0.4   3120   724 pts/1    S+   09:39   0:00 grep sleep
    >>>>> roczei@knowarc2:~$ cr_checkpoint 17113
    >>>>>
    >>>>> So if I send a checkpoint signal to 17113 then the sleep process running will "restart". What do you think why happen this? This error happen with Sun Grid Engine and without SGE too.
    >>>>>
    >>>>> Best regards,
    >>>>>
    >>>>>      Gabor Roczei
    >>>>>
    >>>>>
    >>>>>           
    >>>> -- 
    >>>> Paul H. Hargrove                          PHHargrove_at_lbl_dot_gov
    >>>> Future Technologies Group                 Tel: +1-510-495-2352
    >>>> HPC Research Department                   Fax: +1-510-486-6900
    >>>> Lawrence Berkeley National Laboratory
    >>>>         
    >> -- 
    >> Paul H. Hargrove                          PHHargrove_at_lbl_dot_gov
    >> Future Technologies Group
    >> HPC Research Department                   Tel: +1-510-495-2352
    >> Lawrence Berkeley National Laboratory     Fax: +1-510-486-6900
    >>
    >>     
    >
    >
    >   
    
    
    -- 
    Paul H. Hargrove                          PHHargrove_at_lbl_dot_gov
    Future Technologies Group                 Tel: +1-510-495-2352
    HPC Research Department                   Fax: +1-510-486-6900
    Lawrence Berkeley National Laboratory     
    

  • Next message: Paul H. Hargrove: "Re: BLCR: sleep process checkpointing problem"