What is "Service only ran for XX seconds … Pushing respawn out …"
My app installs a launchd job which watches a file and runs a tool whenever that file changes. The tool typically runs for a few seconds and then terminates itself. This has worked OK for years. Yesterday, however, I noticed that launchd sometimes complains to the system log that my “Service” (??) ran for some number of seconds which is less than 60, and so it is “Pushing respawn out” by the difference in seconds between this duration that it supposedly “ran” and 60. Example: 14/11/16 3:31:54.822 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 25 seconds. Pushing respawn out by 35 seconds. Does anyone have any idea what might be going on? 60 seconds happens to be the ThrottleInterval of the job, not the expected “run” time. Am I running a “Service”? (I don’t think so.) Why might launchd think it needs to be “respawned”? I’m on OS X 10.10.1 (14B17). A sanitized version of my job’s plist, and a filtered console log, are below. I can’t find any of these strings in the latest launchd source, which might be at this link: http://www.opensource.apple.com/source/launchd/launchd-842.92.1/src/ But I’m *really* groping in the dark whenever I visit there. Thank you, Jerry Krinock <?xml version="1.0" encoding="UTF-8"?> <!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd"> <plist version="1.0"> <dict> <key>Label</key> <string>MyLabel</string> <key>Nice</key> <integer>20</integer> <key>ProgramArguments</key> <array> <string>/path/to/MyTool</string> <string>MyArg1</string> <string>MyArg2</string> </array> <key>ThrottleInterval</key> <integer>60</integer> <key>WatchPaths</key> <array> <string>/path/to/MyFile</string> </array> </dict> </plist> 14/11/16 3:22:29.948 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 57 seconds. Pushing respawn out by 3 seconds. 14/11/16 3:25:05.659 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 59 seconds. Pushing respawn out by 1 seconds. 14/11/16 3:26:00.903 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 54 seconds. Pushing respawn out by 6 seconds. 14/11/16 3:30:29.608 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 0 seconds. Pushing respawn out by 60 seconds. 14/11/16 3:31:54.822 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 25 seconds. Pushing respawn out by 35 seconds. 14/11/16 3:33:20.050 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 50 seconds. Pushing respawn out by 10 seconds. 14/11/16 3:34:28.347 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 58 seconds. Pushing respawn out by 2 seconds. 14/11/16 3:48:24.681 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 0 seconds. Pushing respawn out by 60 seconds. 14/11/16 3:49:59.418 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 34 seconds. Pushing respawn out by 26 seconds. 14/11/16 3:51:22.418 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 56 seconds. Pushing respawn out by 4 seconds. 14/11/16 3:52:43.228 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 1 seconds. Pushing respawn out by 59 seconds. 14/11/16 3:54:14.707 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 32 seconds. Pushing respawn out by 28 seconds. 14/11/16 3:56:06.659 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 0 seconds. Pushing respawn out by 60 seconds. 14/11/16 3:57:07.151 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 0 seconds. Pushing respawn out by 60 seconds. 14/11/16 3:58:32.343 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 25 seconds. Pushing respawn out by 35 seconds. 14/11/16 4:00:43.205 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 0 seconds. Pushing respawn out by 60 seconds. 14/11/16 4:04:30.194 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 0 seconds. Pushing respawn out by 60 seconds. 14/11/16 4:06:03.763 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 33 seconds. Pushing respawn out by 27 seconds. 14/11/16 4:07:08.939 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 38 seconds. Pushing respawn out by 22 seconds. 14/11/16 4:08:09.133 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 38 seconds. Pushing respawn out by 22 seconds. 14/11/16 4:10:03.729 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 1 seconds. Pushing respawn out by 59 seconds. 14/11/16 4:11:37.160 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 34 seconds. Pushing respawn out by 26 seconds. 14/11/16 4:12:54.515 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 51 seconds. Pushing respawn out by 9 seconds. 14/11/16 4:14:50.649 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 0 seconds. Pushing respawn out by 60 seconds. 14/11/16 4:16:54.758 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 0 seconds. Pushing respawn out by 60 seconds.
Hi Jerry, It's likely that your job is being relaunched because your WatchPath criterion is firing. Your ThrottleInterval is 60, which means that launchd will require that your job run for at least 60 seconds. If it does not, then launchd will not spawn it again until 60 seconds have passed since the last time it was run. (This is to amortize startup costs.) This behavior is described in launchd.plist(5). By default, it's 10 seconds. You can see why launchd spawned your job on Yosemite by using the `launchctl print` subcommand. See the launchctl(1) man page for details. In that output will be the reason launchd ran the job (if the job is currently running). Also, the sources you're looking at are out of date. launchd in Yosemite was rewritten, and it is part of the libxpc project, which is not open source. Though this particular behavior has not changed in the new implementation. -damien On 16 Nov, 2014, at 02:39, Jerry Krinock <jerry@ieee.org> wrote:
My app installs a launchd job which watches a file and runs a tool whenever that file changes. The tool typically runs for a few seconds and then terminates itself. This has worked OK for years. Yesterday, however, I noticed that launchd sometimes complains to the system log that my “Service” (??) ran for some number of seconds which is less than 60, and so it is “Pushing respawn out” by the difference in seconds between this duration that it supposedly “ran” and 60. Example:
14/11/16 3:31:54.822 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 25 seconds. Pushing respawn out by 35 seconds.
Does anyone have any idea what might be going on? 60 seconds happens to be the ThrottleInterval of the job, not the expected “run” time. Am I running a “Service”? (I don’t think so.) Why might launchd think it needs to be “respawned”?
I’m on OS X 10.10.1 (14B17). A sanitized version of my job’s plist, and a filtered console log, are below.
I can’t find any of these strings in the latest launchd source, which might be at this link: http://www.opensource.apple.com/source/launchd/launchd-842.92.1/src/ But I’m *really* groping in the dark whenever I visit there.
Thank you,
Jerry Krinock
<?xml version="1.0" encoding="UTF-8"?> <!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd"> <plist version="1.0"> <dict> <key>Label</key> <string>MyLabel</string> <key>Nice</key> <integer>20</integer> <key>ProgramArguments</key> <array> <string>/path/to/MyTool</string> <string>MyArg1</string> <string>MyArg2</string> </array> <key>ThrottleInterval</key> <integer>60</integer> <key>WatchPaths</key> <array> <string>/path/to/MyFile</string> </array> </dict> </plist>
14/11/16 3:22:29.948 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 57 seconds. Pushing respawn out by 3 seconds. 14/11/16 3:25:05.659 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 59 seconds. Pushing respawn out by 1 seconds. 14/11/16 3:26:00.903 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 54 seconds. Pushing respawn out by 6 seconds. 14/11/16 3:30:29.608 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 0 seconds. Pushing respawn out by 60 seconds. 14/11/16 3:31:54.822 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 25 seconds. Pushing respawn out by 35 seconds. 14/11/16 3:33:20.050 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 50 seconds. Pushing respawn out by 10 seconds. 14/11/16 3:34:28.347 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 58 seconds. Pushing respawn out by 2 seconds. 14/11/16 3:48:24.681 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 0 seconds. Pushing respawn out by 60 seconds. 14/11/16 3:49:59.418 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 34 seconds. Pushing respawn out by 26 seconds. 14/11/16 3:51:22.418 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 56 seconds. Pushing respawn out by 4 seconds. 14/11/16 3:52:43.228 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 1 seconds. Pushing respawn out by 59 seconds. 14/11/16 3:54:14.707 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 32 seconds. Pushing respawn out by 28 seconds. 14/11/16 3:56:06.659 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 0 seconds. Pushing respawn out by 60 seconds. 14/11/16 3:57:07.151 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 0 seconds. Pushing respawn out by 60 seconds. 14/11/16 3:58:32.343 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 25 seconds. Pushing respawn out by 35 seconds. 14/11/16 4:00:43.205 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 0 seconds. Pushing respawn out by 60 seconds. 14/11/16 4:04:30.194 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 0 seconds. Pushing respawn out by 60 seconds. 14/11/16 4:06:03.763 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 33 seconds. Pushing respawn out by 27 seconds. 14/11/16 4:07:08.939 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 38 seconds. Pushing respawn out by 22 seconds. 14/11/16 4:08:09.133 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 38 seconds. Pushing respawn out by 22 seconds. 14/11/16 4:10:03.729 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 1 seconds. Pushing respawn out by 59 seconds. 14/11/16 4:11:37.160 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 34 seconds. Pushing respawn out by 26 seconds. 14/11/16 4:12:54.515 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 51 seconds. Pushing respawn out by 9 seconds. 14/11/16 4:14:50.649 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 0 seconds. Pushing respawn out by 60 seconds. 14/11/16 4:16:54.758 AM com.apple.xpc.launchd[1]: (MyLabel) Service only ran for 0 seconds. Pushing respawn out by 60 seconds.
_______________________________________________ launchd-dev mailing list launchd-dev@lists.macosforge.org https://lists.macosforge.org/mailman/listinfo/launchd-dev
On 2014 Nov 16, at 13:42, Damien Sorresso <dsorresso@apple.com> wrote:
It's likely that your job is being relaunched because your WatchPath criterion is firing.
Thank you, Damien. That’s probably true.
Your ThrottleInterval is 60, which means that launchd will require that your job run for at least 60 seconds. If it does not, then launchd will not spawn it again until 60 seconds have passed since the last time it was run. (This is to amortize startup costs.) This behavior is described in launchd.plist(5).
It looks like I am using ThrottleInterval just a little differently than what the its designers had in mind. My tool gets its input from stdin, only when it launches. I want ThrottleInterval to *coalesce* and simply *delay* reactions to triggers that occur within the ThrottleInterval of the prior trigger. My tool does not “linger" when the work is done because it is not a “service” that needs to jump on every trigger immediately. Instead of amortizing, it ignores. I am truly using ThrottleInterval as a “throttle”, not as a way to amortize startup costs. So it works as I intend, except that it prints this unnecessary and, I think, somewhat misleading message to the console whenever it runs. When I read “Pushing respawn out by 35 seconds”, I think that an actual respawn has been scheduled, but in fact it is only hypothetical. That log message really means “If (as in “big if”) another trigger occurs within the next 35 seconds, respawning of your job will be delayed until 35 seconds from now”. That’s what I want, not a problem. Is there a better technique than ThrottleInterval to get what I want? If not, do you think Apple might entertain a Bug requesting that the confusing and unnecessary log entries not be made? I noticed another app produced one of them earlier today too.
You can see why launchd spawned your job on Yosemite by using the `launchctl print` subcommand. See the launchctl(1) man page for details. In that output will be the reason launchd ran the job (if the job is currently running).
Very nice; anything to reduce the opacity of launchd is appreciated! This might also be a good place to print that respawn delay information :)
On 16 Nov, 2014, at 13:59, Jerry Krinock <jerry@ieee.org> wrote:
On 2014 Nov 16, at 13:42, Damien Sorresso <dsorresso@apple.com> wrote:
It's likely that your job is being relaunched because your WatchPath criterion is firing.
Thank you, Damien. That’s probably true.
Your ThrottleInterval is 60, which means that launchd will require that your job run for at least 60 seconds. If it does not, then launchd will not spawn it again until 60 seconds have passed since the last time it was run. (This is to amortize startup costs.) This behavior is described in launchd.plist(5).
It looks like I am using ThrottleInterval just a little differently than what the its designers had in mind. My tool gets its input from stdin, only when it launches. I want ThrottleInterval to *coalesce* and simply *delay* reactions to triggers that occur within the ThrottleInterval of the prior trigger. My tool does not “linger" when the work is done because it is not a “service” that needs to jump on every trigger immediately. Instead of amortizing, it ignores. I am truly using ThrottleInterval as a “throttle”, not as a way to amortize startup costs.
So it works as I intend, except that it prints this unnecessary and, I think, somewhat misleading message to the console whenever it runs. When I read “Pushing respawn out by 35 seconds”, I think that an actual respawn has been scheduled, but in fact it is only hypothetical. That log message really means “If (as in “big if”) another trigger occurs within the next 35 seconds, respawning of your job will be delayed until 35 seconds from now”. That’s what I want, not a problem.
Actually, that message is printed if we try and spawn the job but found that it did not run for the requisite minimum time. So the message pretty much means what it said: "I went to spawn you, but you said you need to run for 60 seconds at minimum, and you only ran for 35 seconds last time, so I'm pushing your next spawn out by 25 seconds to emulate that expectation." If no spawn attempt was made, that message does not get printed.
Is there a better technique than ThrottleInterval to get what I want? If not, do you think Apple might entertain a Bug requesting that the confusing and unnecessary log entries not be made? I noticed another app produced one of them earlier today too.
I'm not sure I'm grokking what you're after to be honest.
You can see why launchd spawned your job on Yosemite by using the `launchctl print` subcommand. See the launchctl(1) man page for details. In that output will be the reason launchd ran the job (if the job is currently running).
Very nice; anything to reduce the opacity of launchd is appreciated! This might also be a good place to print that respawn delay information :)
It should be there, printed under "minimum runtime". -damien
On 2014 Nov 17, at 11:04, Damien Sorresso <dsorresso@apple.com> wrote:
I'm not sure I'm grokking what you're after to be honest.
Yes I agree. Please allow me to try again, from scratch… My requirement is to read data from a watched file and process it whenever that file changes. Such a change typically occurs only several times a day, often in bursts of several changes during a few minutes. Some days there may be no changes at all. Furthermore, my processing is not urgent. If the watched file changes three times within a minute, I can be lazy and process all changes at once, a minute or two after the third change has completed. It seems that having a service (process) running 24/7 for this need would be wasteful. Instead, I use launchd with a WatchPath to launch the tool whenever a change is detected. Furthermore, I use ThrottleInterval to coalesce multiple changes into one running of my tool. Finally, my tool does not even have anything like a run loop to keep it running. It just has a main() that reads the file, processes the data, and exits, typically after 10 seconds. So you see there is no “requisite minimum time” for my program to run. The faster it runs, the better! * * * The issue is that the ThrottleInterval gives me these warnings, because it is geared toward “amortizing startup”, instead of minimizing running. Should I be doing things differently? Thanks, Jerry
I just thought of another way to explain it. ThrottleInterval appears designed to throttle *quitting* a process. What I’m trying to do is to throttle *launching* a process.
On 17 Nov, 2014, at 08:45, Jerry Krinock <jerry@ieee.org> wrote:
On 2014 Nov 17, at 11:04, Damien Sorresso <dsorresso@apple.com> wrote:
I'm not sure I'm grokking what you're after to be honest.
Yes I agree. Please allow me to try again, from scratch…
My requirement is to read data from a watched file and process it whenever that file changes. Such a change typically occurs only several times a day, often in bursts of several changes during a few minutes. Some days there may be no changes at all. Furthermore, my processing is not urgent. If the watched file changes three times within a minute, I can be lazy and process all changes at once, a minute or two after the third change has completed.
Yeah... that is not what ThrottleInterval is for.
It seems that having a service (process) running 24/7 for this need would be wasteful. Instead, I use launchd with a WatchPath to launch the tool whenever a change is detected. Furthermore, I use ThrottleInterval to coalesce multiple changes into one running of my tool. Finally, my tool does not even have anything like a run loop to keep it running. It just has a main() that reads the file, processes the data, and exits, typically after 10 seconds.
launchd can't really implement this behavior for you since it does not know what your program is doing. If this is the behavior you want, you should have your program watch the file for changes itself using dispatch(3) sources. In other words, you should be using a run loop to watch for the events you're interested in.
So you see there is no “requisite minimum time” for my program to run. The faster it runs, the better!
* * *
The issue is that the ThrottleInterval gives me these warnings, because it is geared toward “amortizing startup”, instead of minimizing running. Should I be doing things differently?
Yes, you want a run loop. -damien
participants (2)
-
Damien Sorresso
-
Jerry Krinock