CODEWITHSUNDEEP
pythonlinuxloggingmultiprocessing
David
David

Reputation: 18281

On linux using Python 2.7 multiprocessing.Process and logging, how/why is logging sequential?

I have a queue work delagator that spawns 15-25 subprocesses via a custom multiprocessing.Pool(). The individual workers emit 1-3 logging.info messages at 10-15 messages in less then 1000ms and I've noticed that the timestamp is always sequential and never collides with other messages. This suggests to me that there is a shared lock somewhere in multiprocessing or logging but I can't figure out where it is exactly.

This is mostly asked for educational purposes as the software in question is going to be refactored to be async or multithreaded as 90% of real time is in IO ( remote api and not number crunching ).

Logging configuration mirrors Django's as I liked how that was organized:

LOGGING['handlers']['complex_console'] = {'level':'DEBUG', 
    'class':'logging.StreamHandler',         
    'formatter':'complex'
}

LOGGING['loggers']['REDACTED_sync'] = {
'handlers': ['complex_console'],
'propagate': True,
'level':'DEBUG'
}

Some quick clarification, multiprocessing.Process does use fork but calls to logging.getLogger() are not made until after a child-process is spawned.

Upvotes: 0

Views: 244

Answers (2)

Fred Mitchell
Fred Mitchell

Reputation: 2161

If you only have one processor, then the behavior that you get should be expected.

Upvotes: 0

Aida Paul
Aida Paul

Reputation: 2722

I have no idea how your spawner works, but if it follows a very simple schema:

logger = get_logger() # Gets logger instance)

class Foo:
    #Definition

while(True):
    #A loop that spawns processes

Then they will share the same instance of logger, hence why you get "sequential" writes. It doesn't impose any locking that you would notice performance wise. And that is for a very simple reason - appending to a log to file is extremely fast and is almost always finished before this file is needed again.

You can make an experiment and remove file handler from logging and you will notice that they are still sequential as it is very rare occurrence for two processes, even doing exactly the same, to finish at the same time.

Upvotes: 2

Related Questions