Blocking I/O in network thread

[Pushkar Pradhan]

I was going through the code in Diags.cc and I saw that if debug logging is
on, ATS calls vfprintf in the thread that handles the client request.
E.g.
https://github.com/apache/trafficserver/blob/master/src/tscore/Diags.cc#L301

Is this a good idea?
Or is the assumption that if you have turned on debug logging you make this
trade off?

[Daniel Xu]

Yeah that sounds suboptimal. Maybe it’d be good enough to leave a
documentation note and mark fixing this as an intern project or
something.
Writing some off thread logging code and writing a poor man’s multi
producer queue sounds like a pretty nice project.

Daniel

Post by Pushkar Pradhan
I was going through the code in Diags.cc and I saw that if debug
logging is> on, ATS calls vfprintf in the thread that handles the client request.> E.g.
https://github.com/apache/trafficserver/blob/master/src/tscore/Diags.cc#L301>
Is this a good idea?
Or is the assumption that if you have turned on debug logging you
make this> trade off?
--
pushkar

[Alan Carroll]

It's generally accepted that enable logging messages will decrease ATS
performance by roughly an order of magnitude, but as Dan points out, based
on this, we might be able to do better if the output was sent to an AIO
thread. OTOH, if you're trying to track timing / ordering issues, have the
messages come out asynchronously might negate much of the utility.

Post by Daniel Xu
Yeah that sounds suboptimal. Maybe it’d be good enough to leave a
documentation note and mark fixing this as an intern project or
something.
Writing some off thread logging code and writing a poor man’s multi
producer queue sounds like a pretty nice project.
Daniel

Post by Pushkar Pradhan
I was going through the code in Diags.cc and I saw that if debug
logging is> on, ATS calls vfprintf in the thread that handles the client

request.> E.g.
https://github.com/apache/trafficserver/blob/master/src/tscore/Diags.cc#L301

Post by Pushkar Pradhan
Is this a good idea?
Or is the assumption that if you have turned on debug logging you
make this> trade off?
--
pushkar

[Walt Karas]

I think we should consider switching to something like this for debug tracing:

https://godbolt.org/z/Xj1VXZ

It will reduce the performance impact when all debug output is
disabled. It will also reduce the impact even when some debug output
is enabled. This may be helpful for bugs due to race conditions,
where changes in performance can prevent the bug from happening.
On Mon, Oct 15, 2018 at 10:37 AM Alan Carroll

Post by Alan Carroll
It's generally accepted that enable logging messages will decrease ATS
performance by roughly an order of magnitude, but as Dan points out, based
on this, we might be able to do better if the output was sent to an AIO
thread. OTOH, if you're trying to track timing / ordering issues, have the
messages come out asynchronously might negate much of the utility.

Yeah that sounds suboptimal. Maybe it’d be good enough to leave a
documentation note and mark fixing this as an intern project or
something.
Writing some off thread logging code and writing a poor man’s multi
producer queue sounds like a pretty nice project.
Daniel

Post by Pushkar Pradhan
I was going through the code in Diags.cc and I saw that if debug
logging is> on, ATS calls vfprintf in the thread that handles the client

request.> E.g.
https://github.com/apache/trafficserver/blob/master/src/tscore/Diags.cc#L301

Post by Pushkar Pradhan
Is this a good idea?
Or is the assumption that if you have turned on debug logging you
make this> trade off?
--
pushkar

--
*Beware the fisherman who's casting out his line in to a dried up riverbed.*
*Oh don't try to tell him 'cause he won't believe. Throw some bread to the
ducks instead.*
*It's easier that way. *- Genesis : Duke : VI 25-28

[Alan Carroll]

That's interesting - I think we could do that incrementally even.

One of the goals of the BufferWriter formatting effort was to improve
performance for debugging messages as well, mainly by avoiding local
argument formatting if the trace wasn't enabled. IP addresses are the
classic example - to pass them to printf() you need to call inet_ntoa
before printf and therefore before checking the enable flag. BWF lets you
check the flag first, and then do the formatting. You could do a local if
on the flag, then convert, then call the trace (which is done in some
places) but it seems better to automate that.

[Pushkar Pradhan]

1. To log asynchronously can't we use the existing logging code that logs
asynchronously the transactions?
2. Logging inline may produce the messages in order, but wouldn't it cause
heisenbugs?
3. It looks like the current developers/committers don't know whether
logging lnline was intentional or an oversight?

On Mon, Oct 15, 2018 at 8:38 AM Alan Carroll

Post by Alan Carroll
It's generally accepted that enable logging messages will decrease ATS
performance by roughly an order of magnitude, but as Dan points out, based
on this, we might be able to do better if the output was sent to an AIO
thread. OTOH, if you're trying to track timing / ordering issues, have the
messages come out asynchronously might negate much of the utility.

Post by Daniel Xu
Yeah that sounds suboptimal. Maybe it’d be good enough to leave a
documentation note and mark fixing this as an intern project or
something.
Writing some off thread logging code and writing a poor man’s multi
producer queue sounds like a pretty nice project.
Daniel

Post by Pushkar Pradhan
I was going through the code in Diags.cc and I saw that if debug
logging is> on, ATS calls vfprintf in the thread that handles the

client

Post by Daniel Xu
request.> E.g.

https://github.com/apache/trafficserver/blob/master/src/tscore/Diags.cc#L301

Post by Daniel Xu

Post by Pushkar Pradhan
Is this a good idea?
Or is the assumption that if you have turned on debug logging you
make this> trade off?
--
pushkar

--
*Beware the fisherman who's casting out his line in to a dried up riverbed.*
*Oh don't try to tell him 'cause he won't believe. Throw some bread to the
ducks instead.*
*It's easier that way. *- Genesis : Duke : VI 25-28

[Alan Carroll]

1) It might be possible but as noted I'm not sure it wouldn't invalidate
the utility of the logging messages.
2) Yes, it does. Again, it's a matter of which is the lesser evil. I think
synchronous writing for debug messages is the least worst choice.
3) I think it was deliberate.