[Twisted-Python] Names DNS Client too chatty
Hi Guys, I'd like to get ticket 4021 integrated in some fashion into Twisted. Currently, the Twisted Names client issues a "starting" and "stopping" log message on every resolution. It fills up the logs and makes seeing valuable log messages really difficult in the sea of DNS requests. 150,000 resolutions per day is generating 700mb of logs just from the start/stop. The problem is actually the UDP datagram transport that Resolver is based on. 4021 proposes to address the issue by wrapping the two log lines with "if self.noisy". I'd advocate this solution as it leverages the noisy attribute already expected to tamp down log chattiness. Also, it requires the smallest amount of code change as opposed to implementing a filter on the logging system. Honestly this has been a problem for me on more than one project I've used the Names client in. It's just untenable in a project with a high volume. Jean-Paul asked me to bring this up for discussion if I wanted to fix it. What do others think? -J Sent via iPhone Is your e-mail Premiere?
On Sun, 23 Jan 2011 13:03:23 -0700 "Jason J. W. Williams" <jasonjwwilliams@gmail.com> wrote:
Hi Guys,
I'd like to get ticket 4021 integrated in some fashion into Twisted. Currently, the Twisted Names client issues a "starting" and "stopping" log message on every resolution. It fills up the logs and makes seeing valuable log messages really difficult in the sea of DNS requests. 150,000 resolutions per day is generating 700mb of logs just from the start/stop.
The problem is actually the UDP datagram transport that Resolver is based on. 4021 proposes to address the issue by wrapping the two log lines with "if self.noisy".
I'd advocate this solution as it leverages the noisy attribute already expected to tamp down log chattiness. Also, it requires the smallest amount of code change as opposed to implementing a filter on the logging system.
Honestly this has been a problem for me on more than one project I've used the Names client in. It's just untenable in a project with a high volume.
Jean-Paul asked me to bring this up for discussion if I wanted to fix it. What do others think?
Hi Jason, I have experienced such situation a few times just like you. At first I used to invoke twistd redirecting logs to /dev/null but then I commented such Twisted code lines out in order to be able to have useful logs for my applications. I really think such verbose logging should be turned off by default because it is quite useless to the end user and produces huge amounts of logs which are useless as well. Cheers, -- Angelo Dell'Aera 'buffer' Antifork Research, Inc. http://buffer.antifork.org Metro Olografix
On Jan 23, 2011, at 22:45 , Angelo Dell'Aera wrote:
I really think such verbose logging should be turned off by default because it is quite useless to the end user and produces huge amounts of logs which are useless as well.
Cheers,
My 2 cents to this is that responsiveness and performance of an application has turned out to be severely impacted even by console output, disk output of the same data being actually faster. Various tests have consistently shown that being 'distracted' for synchronous write() actually costs noticeable amounts of time. For example, even a simple extraction of linux-2.6.38-rc2.tar.bz2 with and without -v can tell: time tar -xvjf linux-2.6.38-rc2.tar.bz2 (console output to a terminal emulator): real 4m38.434s user 1m30.148s sys 0m40.721 time tar -xvjf linux-2.6.38-rc2.tar.bz2 > filelist.txt: real 3m5.595s (actually faster than console!) user 1m27.162s sys 0m35.854s time tar -xvjf linux-2.6.38-rc2.tar.bz2 > /dev/null: real 2m57.909s (36% faster, now we're talking business) user 1m26.851s sys 0m34.696s (Non-verbose tar -xjf does not make much difference from piping into /dev/null at least on Mac OS X, but probably its being written in C and going through less levels of indirection between if(verbose) check and actual output have contributed to that; turning Twisted's logging off completely invariably gave tremendous performance boosts.) Maybe I'm missing something here, but that's what my experience on several projects said. (Here was going to be the part where I would actually propose some sort of solution but it turned out to be so stupid on the second sight that I decided to scrap it until I work out the details.)
On Jan 23, 2011, at 7:11 PM, Jarosław Fedewicz wrote:
My 2 cents to this is that responsiveness and performance of an application has turned out to be severely impacted even by console output, disk output of the same data being actually faster. Various tests have consistently shown that being 'distracted' for synchronous write() actually costs noticeable amounts of time.
Yes, logging in Twisted is a bit of a mess. Almost all of these chatty little messages should not be logged to disk. If they're logged at all, they should be logged as purely structured data for observers to analyze later, not as text messages to go on a log file. Something like this, maybe: log.msg(interface=INameResolutionLogEvent, name=domain, recordType=type) This will allow log observers to listen for events with event['interface'] == INameResolutionLogEvent, but won't trigger a synchronous write(). One of my dream features for Twisted's logging system is to get ring-buffer logging, like Foolscap has - <http://foolscap.lothar.com/docs/logging.html>. Also, to log a lot less text and a lot more structured stuff that can be examined later without big piles of regular expressions. I'd be happy to describe this in more detail if anyone would like to try to make systematic improvements to our logging subsystem or Twisted's internal use of it :). In the meanwhile, I think it would be OK to just remove these messages entirely.
On Sun, Jan 23, 2011 at 6:39 PM, Glyph Lefkowitz <glyph@twistedmatrix.com> wrote:
Yes, logging in Twisted is a bit of a mess. Almost all of these chatty little messages should not be logged to disk. If they're logged at all, they should be logged as purely structured data for observers to analyze later, not as text messages to go on a log file. Something like this, maybe: log.msg(interface=INameResolutionLogEvent, name=domain, recordType=type) This will allow log observers to listen for events with event['interface'] == INameResolutionLogEvent, but won't trigger a synchronous write(). One of my dream features for Twisted's logging system is to get ring-buffer logging, like Foolscap has - <http://foolscap.lothar.com/docs/logging.html>. Also, to log a lot less text and a lot more structured stuff that can be examined later without big piles of regular expressions. I'd be happy to describe this in more detail if anyone would like to try to make systematic improvements to our logging subsystem or Twisted's internal use of it :). In the meanwhile, I think it would be OK to just remove these messages entirely.
During dev I do like being able to see the "starting/stopping" messages...helps you know what's going on when you're debugging. Would it be that bad to just use a noisy check to toggle these on and off until a better logging system is available? -J
On Sun, Jan 23, 2011 at 7:27 PM, Glyph Lefkowitz <glyph@twistedmatrix.com> wrote:
On Jan 23, 2011, at 9:21 PM, Jason J. W. Williams wrote:
Would it be that bad to just use a noisy check to toggle these on and off until a better logging system is available?
No, that sounds like a fine solution for the interim.
OK so the only other question is, should noisy default to True or False? If we all can agree on that, I'll make the patch match and add tests. -J
On Jan 23, 2011, at 9:29 PM, Jason J. W. Williams wrote:
On Sun, Jan 23, 2011 at 7:27 PM, Glyph Lefkowitz <glyph@twistedmatrix.com> wrote:
On Jan 23, 2011, at 9:21 PM, Jason J. W. Williams wrote:
Would it be that bad to just use a noisy check to toggle these on and off until a better logging system is available?
No, that sounds like a fine solution for the interim.
OK so the only other question is, should noisy default to True or False? If we all can agree on that, I'll make the patch match and add tests.
-J
Personally I'd say 'false'. This is technically a change in behavior, but I don't think that we should make guarantees about emitted log messages. Practically speaking, I've never seen any code which would care about an unstructured log message. Anyone else object to changing it?
On 01/24/2011 02:43 AM, Glyph Lefkowitz wrote:
Personally I'd say 'false'. This is technically a change in behavior, but I don't think that we should make guarantees about emitted log messages. Practically speaking, I've never seen any code which would care about an unstructured log message. Anyone else object to changing it?
I'm strongly in favour of setting noisy to False on all factory objects; I find their logging tedious, and have a bunch of monkeypatch code in most of my projects to import the modules and set the class variable, to I don't have to subclass just to do that. The structured logging proposal sounds interesting and I'm potentially willing to give it a go. However, it seems like it would be a lot of work and that it would be very likely to sit in Trac review limbo for a while (getting ever-harder to merge the branch back in). (This is not intended as a criticism - merely an observation that even tickets for simple problems with patches take a while to get reviewed, as manpower is of course a precious and scarce resource) Do you have any thoughts on how it could be broken down into smaller chunks?
On 10:40 am, p.mayers@imperial.ac.uk wrote:
On 01/24/2011 02:43 AM, Glyph Lefkowitz wrote:
Personally I'd say 'false'. This is technically a change in behavior, but I don't think that we should make guarantees about emitted log messages. Practically speaking, I've never seen any code which would care about an unstructured log message. Anyone else object to changing it?
I'm strongly in favour of setting noisy to False on all factory objects; I find their logging tedious, and have a bunch of monkeypatch code in most of my projects to import the modules and set the class variable, to I don't have to subclass just to do that.
The structured logging proposal sounds interesting and I'm potentially willing to give it a go. However, it seems like it would be a lot of work and that it would be very likely to sit in Trac review limbo for a while (getting ever-harder to merge the branch back in).
I don't think it would be a lot of work. Glyph already implemented 1/3rd of it in a previous email in this thread. The rest is adding a dict of lists of observers to LogPublisher (replacing the current list of observers) and obviously writing some unit tests.
(This is not intended as a criticism - merely an observation that even tickets for simple problems with patches take a while to get reviewed, as manpower is of course a precious and scarce resource)
Do you have any thoughts on how it could be broken down into smaller chunks?
All of the actual log messages throughout Twisted should *not* be changed at once. They should be changed incrementally, as people care about them or work on code related to them. Jean-Paul
If there's no objections the rest of today, I'll make sure the 4021 patch still applies and see what could be done as a test. -J On Mon, Jan 24, 2011 at 3:40 AM, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 01/24/2011 02:43 AM, Glyph Lefkowitz wrote:
Personally I'd say 'false'. This is technically a change in behavior, but I don't think that we should make guarantees about emitted log messages. Practically speaking, I've never seen any code which would care about an unstructured log message. Anyone else object to changing it?
I'm strongly in favour of setting noisy to False on all factory objects; I find their logging tedious, and have a bunch of monkeypatch code in most of my projects to import the modules and set the class variable, to I don't have to subclass just to do that.
The structured logging proposal sounds interesting and I'm potentially willing to give it a go. However, it seems like it would be a lot of work and that it would be very likely to sit in Trac review limbo for a while (getting ever-harder to merge the branch back in).
(This is not intended as a criticism - merely an observation that even tickets for simple problems with patches take a while to get reviewed, as manpower is of course a precious and scarce resource)
Do you have any thoughts on how it could be broken down into smaller chunks?
_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
On 05:24 pm, jasonjwwilliams@gmail.com wrote:
If there's no objections the rest of today, I'll make sure the 4021 patch still applies and see what could be done as a test.
I think it would be sad to lose the port starting up log messages. Sure, they're a nuisance if you start and stop 50k ports per second. However, they're just what you want if you have a boring server that starts one or two ports in the entire lifetime of your application. For clients, the common case is to start and stop many connectors over the lifetime of an application, so it sounds slightly more tolerable to disable these by default. However, even for clients I've found these messages useful. For example they've revealed bugs in buildbot's reconnection code. So I doubt it's a pure win to disable these by default (just like it's not a pure win to have them enabled by default). As long as someone's going to touch this code, it seems like it would be better to just implement structured logging. This doesn't even have to mean changes to LogPublisher. It could mean replacing: log.msg("%s starting on %s"%(self.protocol.__class__, self._realPortNumber)) with: log.msg( event_source=self, event_type="start", protocol=self.protocol, port_number=self._realPortNumber) (and documenting and testing). It may well be nice to have LogPublisher be able to dispatch these more efficiently, but that's just an optimization. This still has the effect of disabling the messages by default. And (for now) it's even harder to turn them back on (you need a log observer that can report about these events, instead of just setting a flag). But it's better in the long run, right? Jean-Paul
-J
On Mon, Jan 24, 2011 at 3:40 AM, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 01/24/2011 02:43 AM, Glyph Lefkowitz wrote:
Personally I'd say 'false'. �This is technically a change in behavior, but I don't think that we should make guarantees about emitted log messages. �Practically speaking, I've never seen any code which would care about an unstructured log message. �Anyone else object to changing it?
I'm strongly in favour of setting noisy to False on all factory objects; I find their logging tedious, and have a bunch of monkeypatch code in most of my projects to import the modules and set the class variable, to I don't have to subclass just to do that.
The structured logging proposal sounds interesting and I'm potentially willing to give it a go. However, it seems like it would be a lot of work and that it would be very likely to sit in Trac review limbo for a while (getting ever-harder to merge the branch back in).
(This is not intended as a criticism - merely an observation that even tickets for simple problems with patches take a while to get reviewed, as manpower is of course a precious and scarce resource)
Do you have any thoughts on how it could be broken down into smaller chunks?
_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
In my opinion this has been a problem for a very long time, and it would be better to have a correction that fits the majority of cases with a small code change now rather than wait for the perfect log system. These changes don't preclude a better logger and way of filtering these out in the future. self.noisy may be viewed as a hack, but honestly it's worked well for me and it's easy to understand what it does. If the compromise is the 4021 patch (wrapping with "if self.noisy"), with noisy defaulting to True, I think that's a good solution today without precluding the perfect solution when someone wants to build it. -J On Mon, Jan 24, 2011 at 11:09 AM, <exarkun@twistedmatrix.com> wrote:
On 05:24 pm, jasonjwwilliams@gmail.com wrote:
If there's no objections the rest of today, I'll make sure the 4021 patch still applies and see what could be done as a test.
I think it would be sad to lose the port starting up log messages. Sure, they're a nuisance if you start and stop 50k ports per second. However, they're just what you want if you have a boring server that starts one or two ports in the entire lifetime of your application.
For clients, the common case is to start and stop many connectors over the lifetime of an application, so it sounds slightly more tolerable to disable these by default. However, even for clients I've found these messages useful. For example they've revealed bugs in buildbot's reconnection code.
So I doubt it's a pure win to disable these by default (just like it's not a pure win to have them enabled by default).
As long as someone's going to touch this code, it seems like it would be better to just implement structured logging. This doesn't even have to mean changes to LogPublisher. It could mean replacing:
log.msg("%s starting on %s"%(self.protocol.__class__, self._realPortNumber))
with:
log.msg( event_source=self, event_type="start", protocol=self.protocol, port_number=self._realPortNumber)
(and documenting and testing). It may well be nice to have LogPublisher be able to dispatch these more efficiently, but that's just an optimization.
This still has the effect of disabling the messages by default. And (for now) it's even harder to turn them back on (you need a log observer that can report about these events, instead of just setting a flag). But it's better in the long run, right?
Jean-Paul
-J
On Mon, Jan 24, 2011 at 3:40 AM, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 01/24/2011 02:43 AM, Glyph Lefkowitz wrote:
Personally I'd say 'false'. This is technically a change in behavior, but I don't think that we should make guarantees about emitted log messages. Practically speaking, I've never seen any code which would care about an unstructured log message. Anyone else object to changing it?
I'm strongly in favour of setting noisy to False on all factory objects; I find their logging tedious, and have a bunch of monkeypatch code in most of my projects to import the modules and set the class variable, to I don't have to subclass just to do that.
The structured logging proposal sounds interesting and I'm potentially willing to give it a go. However, it seems like it would be a lot of work and that it would be very likely to sit in Trac review limbo for a while (getting ever-harder to merge the branch back in).
(This is not intended as a criticism - merely an observation that even tickets for simple problems with patches take a while to get reviewed, as manpower is of course a precious and scarce resource)
Do you have any thoughts on how it could be broken down into smaller chunks?
_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
_______________________________________________ Twisted-Python mailing list Twisted-Python@twistedmatrix.com http://twistedmatrix.com/cgi-bin/mailman/listinfo/twisted-python
On Jan 24, 2011, at 1:18 PM, Jason J. W. Williams wrote:
In my opinion this has been a problem for a very long time, and it would be better to have a correction that fits the majority of cases with a small code change now rather than wait for the perfect log system. These changes don't preclude a better logger and way of filtering these out in the future. self.noisy may be viewed as a hack, but honestly it's worked well for me and it's easy to understand what it does.
If the compromise is the 4021 patch (wrapping with "if self.noisy"), with noisy defaulting to True, I think that's a good solution today without precluding the perfect solution when someone wants to build it.
While I agree with the general sentiment (incremental improvements that can be done now are pretty much always better than gigantic overhauls that have to be put off until later) the current logging system is already pretty much designed for this, we're just not using it right. Trimming JP's message a bit to just the key part:
This doesn't even have to mean changes to LogPublisher. It could mean replacing:
log.msg("%s starting on %s"%(self.protocol.__class__, self._realPortNumber))
with:
log.msg( event_source=self, event_type="start", protocol=self.protocol, port_number=self._realPortNumber)
(and documenting and testing). It may well be nice to have LogPublisher be able to dispatch these more efficiently, but that's just an optimization.
That is _literally_ all that needs to be done to preserve the functionality JP likes. You don't have to change the implementation of log.msg: it already accepts **kw, specifically for this reason. A message logged in this manner (with no "message" or "format" event key) will produce no text output in the log. So the amount of work involved is really just writing one line of code. Which JP already wrote, here. It just needs a unit test and a review :). I do wonder why he went with the PEP8-style underscore parameter names rather than Twisted-style intercapped names though :). -glyph P.S.: In the future, please reply inline, it's standard etiquette for this list.
On Mon, Jan 24, 2011 at 10:01 PM, Glyph Lefkowitz <glyph@twistedmatrix.com> wrote:
While I agree with the general sentiment (incremental improvements that can be done now are pretty much always better than gigantic overhauls that have to be put off until later) the current logging system is already pretty much designed for this, we're just not using it right. Trimming JP's message a bit to just the key part:
This doesn't even have to mean changes to LogPublisher. It could mean replacing:
log.msg("%s starting on %s"%(self.protocol.__class__,
self._realPortNumber))
with:
log.msg(
event_source=self,
event_type="start",
protocol=self.protocol,
port_number=self._realPortNumber)
Playing with this a bit, the above change does indeed blackhole the log message. The question then is how someone can get these actually outputted the log when they want to. Right now the TCP unit test for test_connectionLostLogMsg expects textual output to the log. I'm re-working the test to instead expect the dict with the same values passed in, but that just ensures the data is properly passed to log.msg() not that it's going to show up if you want it to. -J
On Jan 24, 2011, at 8:09 PM, exarkun@twistedmatrix.com wrote:
On 05:24 pm, jasonjwwilliams@gmail.com wrote:
If there's no objections the rest of today, I'll make sure the 4021 patch still applies and see what could be done as a test.
I think it would be sad to lose the port starting up log messages. Sure, they're a nuisance if you start and stop 50k ports per second. However, they're just what you want if you have a boring server that starts one or two ports in the entire lifetime of your application.
I think the fail of it all is that all factories, by default, are noisy unless explicitly declared quiet, without an option to be quiet unless explicitly declared noisy. I've had this problem with t.web. Sure it's good to have every access logged the moment it arrives, especially if it's just your plain old boring webserver, but it stops being fun when the server is tasked to interface with a special client software which is expected to routinely make 1000–2000 requests per second. I've never made it to 1000 per second on decent hardware, and that's sad. Now the project is in Perl, it has some scalability and codebase issues, but at least it copes with event pressure. :-( It would surely be nice to have a logger which flushes out, say, every 2000 messages or every few seconds, whichever comes first (it would be a lot more filesystem efficient), suitable if you have a freaking lot of events, you need to log them all and you are not stock broker (in which case integrity really prevails over speed) or you have the integrity taken care about elsewhere (say it's in a postgresql database with good settings). The sad thing is that I haven't figured out how to make my own logger, how to tell everything to use it and how to shut irrelevant server parts up without hacks. Maybe folks refactoring the documentation will come up with something. -- Yaroslav Fedevych Software Developer and Consultant jaroslaw.fedewicz@gmail.com +380685061839, +380969783173
On 06:25 pm, jaroslaw.fedewicz@gmail.com wrote:
It would surely be nice to have a logger which flushes out, say, every 2000 messages or every few seconds, whichever comes first (it would be a lot more filesystem efficient), suitable if you have a freaking lot of events, you need to log them all and you are not stock broker (in which case integrity really prevails over speed) or you have the integrity taken care about elsewhere (say it's in a postgresql database with good settings).
The sad thing is that I haven't figured out how to make my own logger, how to tell everything to use it and how to shut irrelevant server parts up without hacks. Maybe folks refactoring the documentation will come up with something.
http://twistedmatrix.com/documents/current/core/howto/logging.html should answer at least a couple of those questions. Jean-Paul
participants (7)
-
Angelo Dell'Aera -
exarkun＠twistedmatrix.com -
Glyph Lefkowitz -
Jarosław Fedewicz -
Jason J. W. Williams -
Phil Mayers -
Yaroslav Fedevych