torfsen/service

Daemon takes a long time to start up.

RichardBronosky opened this issue · 3 comments

Running the Quickstart takes 16 seconds before the fir message shows up in the syslog. Why is it so slow?

I cannot reproduce this issue over here:

$ date && ./service_quickstart.py start
Mi 6. Jun 22:13:30 CEST 2018
$ tail /var/log/syslog
Jun  6 22:13:33 I'm working...

That's a 3 second delay for me. Your 16 seconds obviously does sound longer than expected.

If you use the latest development version from master you can enable debug logging in the service as follows, this should give you an idea where the time is spent. In the quickstart code, replace the line self.logger.setLevel(logging.INFO) (line 12) with the following:

import service
self.logger.setLevel(service.SERVICE_DEBUG)

Please post the resulting syslog messages.

I got the same issue like @RichardBronosky describes

pi@raspberrypi:~ $ python ~/bin/Messmain.py stop
pi@raspberrypi:~ $ python ~/bin/Messmain.py start
pi@raspberrypi:~ $ tail /var/log/syslog -n 20
Jun 17 15:13:39 raspberrypi I'm working...
Jun 17 15:13:44 raspberrypi I'm working...
Jun 17 15:13:49 raspberrypi I'm working...
Jun 17 15:13:54 raspberrypi I'm working...
Jun 17 15:13:59 raspberrypi I'm working...
Jun 17 15:14:04 raspberrypi I'm working...
Jun 17 15:14:09 raspberrypi I'm working...
Jun 17 15:14:13 raspberrypi Received SIGTERM signal
Jun 17 15:14:14 raspberrypi `run` returned without exception
Jun 17 15:14:14 raspberrypi PID file has been released
Jun 17 15:14:27 raspberrypi Daemon has detached
Jun 17 15:14:27 raspberrypi Process title has been set
Jun 17 15:14:46 raspberrypi Daemon context has been established
Jun 17 15:14:46 raspberrypi PID file has been acquired
Jun 17 15:14:46 raspberrypi Calling `run`
Jun 17 15:14:46 raspberrypi I'm working...
Jun 17 15:14:51 raspberrypi I'm working...
Jun 17 15:14:56 raspberrypi I'm working...
Jun 17 15:15:01 raspberrypi I'm working...
Jun 17 15:15:06 raspberrypi I'm working...

With following code
started with python ~/bin/Messmain.py start

import logging
from logging.handlers import SysLogHandler
import time

from service import find_syslog, Service

class MyService(Service):
    def __init__(self, *args, **kwargs):
        super(MyService, self).__init__(*args, **kwargs)
        self.logger.addHandler(SysLogHandler(address=find_syslog(),
                               facility=SysLogHandler.LOG_DAEMON))
        import service
        self.logger.setLevel(service.SERVICE_DEBUG)

    def run(self):
        while not self.got_sigterm():
            self.logger.info("I'm working...")
            time.sleep(5)

if __name__ == '__main__':
    import sys

    if len(sys.argv) != 2:
        sys.exit('Syntax: %s COMMAND' % sys.argv[0])

    cmd = sys.argv[1].lower()
    service = MyService('my_service', pid_dir='/tmp')

    if cmd == 'start':
        service.start()
    elif cmd == 'stop':
        service.stop()
    elif cmd == 'status':
        if service.is_running():
            print "Service is running."
        else:
            print "Service is not running."
    else:
        sys.exit('Unknown command "%s".' % cmd)

Thanks for your investigation, @Relx101! Judging from your logs, a long time is spent between the following two lines:

Jun 17 15:14:27 raspberrypi Process title has been set
Jun 17 15:14:46 raspberrypi Daemon context has been established

These correspond to this and this line in the code. The only thing that happens between those is the call to daemon.DaemonContext (part of the python-daemon package). That call does many things (see PEP 3143 for details), and right now I'm not sure which of these is taking so long in your cases.

Since this seems to be an issue with the python-daemon package, I suggest you open a ticket on their issues page. There is also an existing issue filed for python-daemon regarding long start up times, which might be related to your problem.

I'm closing this issue, since this seems impossible to fix from within the service package. Feel free to re-open if you have ideas on how to work around or solve the problem inside service.