* PRBLEM: performance issues
According to branko, numerous debug-level apr_psprintf's add up fast
and hurt performance. It's bad to create these messages when
debug-level logging isn't even turned on.
Possible Solutions?
The logging API can still do the loglevel-test, but server
processes should cache the repository's loglevel and avoid
constructing messages when they can. This can be documented as a
'best practice', or we can create a macro like branko demonstrated.
* PRBLEM: logging errors or requests not associated with repositories.
Sometimes errors happen before a repository is opened, or requests
come in on bogus URLs. This is still interesting stuff to log.
Where/how should it be done?
Possible Solutions?
mod_dav_svn is already logging these sorts of things in apache's
own logs. But svnserve is still out in the cold. Perhaps
svnserve can have private code to write such things to logs in
/etc/subversion? should this be shared code as well, making
mod_dav_svn use it too? How do we make a clean conceptual
distinction between per-repository logfiles and 'global' ones?
* PRBLEM: lots of processes all trying to write to logfiles.
How do we mediate write access to a single logfile with N processes
all trying to write to it at once?
Possible Solutions?
flock() style stuff, like the 'write lock' in FSFS?
To unsubscribe, e-mail: dev-unsubscribe (AT) subversion (DOT) tigris.org
For additional commands, e-mail: dev-help (AT) subversion (DOT) tigris.org

Ben Collins-Sussman wrote:

* PRBLEM: logging errors or requests not associated with repositories.

Sometimes errors happen before a repository is opened, or requests
come in on bogus URLs. This is still interesting stuff to log.
Where/how should it be done?

Possible Solutions?

mod_dav_svn is already logging these sorts of things in apache's
own logs. But svnserve is still out in the cold. Perhaps
svnserve can have private code to write such things to logs in
/etc/subversion? should this be shared code as well, making
mod_dav_svn use it too? How do we make a clean conceptual
distinction between per-repository logfiles and 'global' ones?

How about

Per-repos logfiles are specified in the repos config file. If there is
no per-repos logfile, or the config file can't be parsed or something
thus we can't find out about it anyway we fall back to a global log
file. The global logfile is controlled by an svnserve command line
option or an / directive, if no global
logfile is set up then no logging happens, the same situation we have
currently.
-garrett

To unsubscribe, e-mail: dev-unsubscribe (AT) subversion (DOT) tigris.org
For additional commands, e-mail: dev-help (AT) subversion (DOT) tigris.org

Jul 15, 2005, at 10:29 AM, Garrett Rooney wrote:

Per-repos logfiles are specified in the repos config file. If
there is no per-repos logfile, or the config file can't be parsed
or something thus we can't find out about it anyway we fall back to
a global log file. The global logfile is controlled by an svnserve
command line option or an /
directive, if no global logfile is set up then no logging happens,
the same situation we have currently.

Yeah, but at the same time, it feels weirdly, overly complex to me.

I mean, imagine that a repository is correctly set up to have private
logfiles. Several confused users try accessing the wrong URL and get
rejected; these accesses end up in the global logs. But then the
users get the URL correct, and so their accesses are now going into
the repository's private logs. Hm.

When admins ask, "hey, where do I find svnserve's logs?", the answer
is now "look in two or more places, possibly".

It makes me wonder, honestly, if the 'errorlog' shouldn't be
completely global, all of the time, and can cover all debugging/error
messages for all repositories. We could decide that the *only* per-
repository logs are individual accesslogs.

To unsubscribe, e-mail: dev-unsubscribe (AT) subversion (DOT) tigris.org
For additional commands, e-mail: dev-help (AT) subversion (DOT) tigris.org

Fri, 2005-07-15 at 10:23 -0500, Ben Collins-Sussman wrote:
The logging API can still do the loglevel-test, but server
processes should cache the repository's loglevel and avoid
constructing messages when they can. This can be documented as a
'best practice', or we can create a macro like branko demonstrated.

My advice is to ignore Branko's concern until it becomes an issue; when
it does, we can optimize performance in successive steps by (1) querying
the log level to avoid creating arguments, and (2) caching the log level
to avoid making any function calls.

But this brings up another point: your svn_repos_write_accesslog()
(which is much too long of a name for a commonly-called function,
incidentally) should take a variable argument list. Then, at least the
top-level apr_snprintf can be avoided whenever the log level is too low,
and there is no performance issue in the common case where the arguments
are readily available.

* PRBLEM: logging errors or requests not associated with repositories.

I tentatively agree with your later conclusion that only access logs
should be per-repository, and that we should leave error logging to the
servers.

* PRBLEM: lots of processes all trying to write to logfiles.

In Unix land, at least, if you open a file for append on a local
filesystem, write() is atomic. So generally logging wins because the
log messages fit within the buffer size and are written out with a
single write().

File locking could create performance issues and deadlock issues, and I
advise against going down that path.

To unsubscribe, e-mail: dev-unsubscribe (AT) subversion (DOT) tigris.org
For additional commands, e-mail: dev-help (AT) subversion (DOT) tigris.org

Jul 15, 2005, at 10:53 AM, John Peacock wrote:

I think the public API is too low level to begin with. Each
process should be calling a logger, which is the only code that
handles writing and the only code which knows to where the log is
being written.

What is a 'logger'? A whole new svn-logging-daemon process?

I see only two options: write a whole new logging daemon, or use
some sort of file-locking to mediate access.

It would also solve the apr_psprintf performance issues if there
was an opaque logger object that contained the loglevel, so that
all code could do something like this [horrible pseudocode]:

if this_event_level < logger.loglevel
logger.log_error(moderately expensive apr_psprintf)

Yes, that's basically what Branko was suggesting.

To unsubscribe, e-mail: dev-unsubscribe (AT) subversion (DOT) tigris.org
For additional commands, e-mail: dev-help (AT) subversion (DOT) tigris.org

Fri, 2005-07-15 at 11:53 -0400, John Peacock wrote:
It would also solve the apr_psprintf performance issues if there was an
opaque logger object that contained the loglevel, so that all code could
do something like this [horrible pseudocode]:

if this_event_level < logger.loglevel
logger.log_error(moderately expensive apr_psprintf)

thus making it completely natural to avoid a potentially expensive test,
as well as remove the need for each place to cache the loglevel
individually.

I'm baffled by this argument. We can do exactly the same thing in Ben's
API, except that logger.loglevel is a function call. But you proposed
that the logger be an "opaque" object, so presumably logger.loglevel
would also be a function call.

To unsubscribe, e-mail: dev-unsubscribe (AT) subversion (DOT) tigris.org
For additional commands, e-mail: dev-help (AT) subversion (DOT) tigris.org

Jul 15, 2005, at 11:02 AM, Greg Hudson wrote:

But this brings up another point: your svn_repos_write_accesslog()
(which is much too long of a name for a commonly-called function,
incidentally) should take a variable argument list. Then, at least
the
top-level apr_snprintf can be avoided whenever the log level is too
low,
and there is no performance issue in the common case where the
arguments
are readily available.

Excellent idea, consider me sold. Will do.


>
>* PRBLEM: logging errors or requests not associated with
>repositories.
>>
>
I tentatively agree with your later conclusion that only access logs
should be per-repository, and that we should leave error logging to
the
servers.

I'm not sure what this plan looks like, though.

Are we talking about tossing *all* mention of errorlog (and loglevel)
in the public API, and just make the API talk about per-repos
accesslog? (In which case, mod_dav_svn continues logging errors to
apache's errorlog, and svnserve grows some private errorlog/loglevel
ability that goes into /etc/subversion/)

, should we still have a notion of a 'shared' errorlog in /etc/
subversion, usable via a public API? (The public API just wouldn't
make use of svn_repos_t; it would be more generically available to
all servers.)

I'm thinking that the latter option is still more attractive, because
the sorts of errors that mod_dav_svn logs into apache's system are
very low-level and unfriendly. I'd like mod_dav_svn to be able to
log more intellible, svn-specific errors into an svn-specific errorlog.


>
>* PRBLEM: lots of processes all trying to write to logfiles.
>>
>
In Unix land, at least, if you open a file for append on a local
filesystem, write() is atomic. So generally logging wins because the
log messages fit within the buffer size and are written out with a
single write().

Hm, I wonder if we're okay on windows as well or if APR makes any
such atomic write guarantees in general

To unsubscribe, e-mail: dev-unsubscribe (AT) subversion (DOT) tigris.org
For additional commands, e-mail: dev-help (AT) subversion (DOT) tigris.org

Jul 15, 2005, at 11:36 AM, Ben Collins-Sussman wrote:

Are we talking about tossing *all* mention of errorlog (and
loglevel) in the public API, and just make the API talk about per-
repos accesslog? (In which case, mod_dav_svn continues logging
errors to apache's errorlog, and svnserve grows some private
errorlog/loglevel ability that goes into /etc/subversion/)

, should we still have a notion of a 'shared' errorlog in /etc/
subversion, usable via a public API? (The public API just wouldn't
make use of svn_repos_t; it would be more generically available to
all servers.)

<sussmando you think it's still worthwhile having a generic
'global' errorlog API, one which servers can share, and has nothing
to do with svn_repos_t?

<ghudsonIt never seemed very important to me.

<ghudsonI'll note that if mod_dav_svn wants to log more informative
errors, it can do so to the Apache log

So perhaps I'll go for the simpler option: let errorlogging (and
'loglevels') be something completely internal to the server. Apache
already has it, and someone will need to implement it for svnserve.
(Maybe me, maybe someone else.)

To unsubscribe, e-mail: dev-unsubscribe (AT) subversion (DOT) tigris.org
For additional commands, e-mail: dev-help (AT) subversion (DOT) tigris.org

Fri, 2005-07-15 at 13:45 -0500, kfogel (AT) collab (DOT) net wrote:
Greg: I'm not sure why you don't want to follow Brane's advice on
this. The macro is easy to write, it ensures we won't ever have that
problem, and it's no harder to use. Seems like a win all around. Am
I missing something?

I'm not sure if the macro comes out as simply as you think it does, and
I also have a strong distaste for macros.

To unsubscribe, e-mail: dev-unsubscribe (AT) subversion (DOT) tigris.org
For additional commands, e-mail: dev-help (AT) subversion (DOT) tigris.org

Greg Hudson <ghudson (AT) MIT (DOT) EDUwrites:
Fri, 2005-07-15 at 13:45 -0500, kfogel (AT) collab (DOT) net wrote:
Greg: I'm not sure why you don't want to follow Brane's advice on
this. The macro is easy to write, it ensures we won't ever have that
problem, and it's no harder to use. Seems like a win all around. Am
I missing something?

I'm not sure if the macro comes out as simply as you think it does,

Then there's prematurity both ways -- can we wait and see whether the
macro actually does make things more complex?

and I also have a strong distaste for macros.

You'll like these, honey. They don't taste like macros, I cooked them
with capers and garlic

To unsubscribe, e-mail: dev-unsubscribe (AT) subversion (DOT) tigris.org
For additional commands, e-mail: dev-help (AT) subversion (DOT) tigris.org

7/15/05, Greg Hudson <ghudson (AT) mit (DOT) eduwrote:

Sat, 2005-07-16 at 01:34 +0200, Branko wrote:
#define SVN_REPS_WRITE_ERRRLG(repo, level, process, message, pool) \
while { \
svn_repos_loglevel_t loglevel; \
SVN_ERR (svn_repos_get_loglevel (&loglevel, (repo), (pool))); \
if ((level) <= loglevel) \
SVN_ERR (svn_repos_write_errorlog ((repo), (level), (process), \
(message), (pool))); \
} while (0)

Sorry if I missed this before.

Well, we're back to my distaste for non-trivial macros.

Perhaps more convincingly, if the write_errorlog() function takes a
variable argument list as I suggested, we can't wrap that in a macro
without C99 tricks or an extra set of parentheses (and even that trick
won't work right, since we need to get at one of the arguments).

I'm in agreement with Brane on the macros. Personally I have no qualms with
macros if they are used carefully. I think in this case, what macros buy us
far outweighs their evils.

First of all, lets clean up this macro with the most recent changes:

#define svn_repos_write_errorlog(repos, log_level, message) \
do { \
if ((repos)->error_log->level <= log_level) \
svn_log_write((repos)->error_log, log_level, message) \
} while(0);

The value of the macro here is huge. The macro allows us to:
* enforce a constant method of logging that checks the log level before
calling the function
* prevents us from processing the 'message' parameter when unnecessary.
* makes our code much more readable.
* makes logging simple from a programmer perspective while keeping things
efficient.
* we can easily make changes to logic by changing the macro (like checking
if repos or repos->error_log is null before calling the function) or we
could completely (and possibly selectively) remove the logging code
altogether.

Logging is one place where I believe macros perform beautifully.

I'm not sure what to say about the var args. It is true that using a macro
will not allow us to use var args cleanly. However, do we really need to use
varargs and does it outweight my purported benefits?
- Brian Holmes

To unsubscribe, e-mail: dev-unsubscribe (AT) subversion (DOT) tigris.org
For additional commands, e-mail: dev-help (AT) subversion (DOT) tigris.org

7/19/05, Brian Holmes <svndev (AT) gmail (DOT) comwrote:

7/15/05, Greg Hudson <ghudson (AT) mit (DOT) eduwrote:

Sat, 2005-07-16 at 01:34 +0200, Branko wrote:
#define SVN_REPS_WRITE_ERRRLG(repo, level, process, message, pool)
\
while { \
svn_repos_loglevel_t loglevel; \
SVN_ERR (svn_repos_get_loglevel (&loglevel, (repo), (pool))); \
if ((level) <= loglevel) \
SVN_ERR (svn_repos_write_errorlog ((repo), (level), (process), \
(message), (pool))); \
} while (0)

Sorry if I missed this before.

Well, we're back to my distaste for non-trivial macros.

Perhaps more convincingly, if the write_errorlog() function takes a
variable argument list as I suggested, we can't wrap that in a macro
without C99 tricks or an extra set of parentheses (and even that trick
won't work right, since we need to get at one of the arguments).

I'm in agreement with Brane on the macros. Personally I have no qualms
with macros if they are used carefully. I think in this case, what macros
buy us far outweighs their evils.

First of all, lets clean up this macro with the most recent changes:

#define svn_repos_write_errorlog(repos, log_level, message) \
do { \
if ((repos)->error_log->level <= log_level) \
svn_log_write((repos)->error_log, log_level, message) \
} while(0);

The value of the macro here is huge. The macro allows us to:
* enforce a constant method of logging that checks the log level before
calling the function
* prevents us from processing the 'message' parameter when unnecessary.
* makes our code much more readable.
* makes logging simple from a programmer perspective while keeping things
efficient.
* we can easily make changes to logic by changing the macro (like checking
if repos or repos->error_log is null before calling the function) or we
could completely (and possibly selectively) remove the logging code
altogether.

Logging is one place where I believe macros perform beautifully.

I'm not sure what to say about the var args. It is true that using a macro
will not allow us to use var args cleanly. However, do we really need to use
varargs and does it outweight my purported benefits?
- Brian Holmes

To unsubscribe, e-mail: dev-unsubscribe (AT) subversion (DOT) tigris.org
For additional commands, e-mail: dev-help (AT) subversion (DOT) tigris.org

, that macro needs protection:

#define svn_repos_write_errorlog(repos, log_level, message) \
do { \
if ((repos)->error_log->level <= (log_level)) \
svn_log_write((repos)->error_log, (log_level), (message)) \
} while(0);

Brian Holmes <svndev (AT) gmail (DOT) comwrites:
Logging is one place where I believe macros perform beautifully.

I'm not sure what to say about the var args. It is true that using a macro
will not allow us to use var args cleanly. However, do we really need to use
varargs and does it outweight my purported benefits?

Anyway, why not just use apr_psprintf() for vararg-based messages?

To unsubscribe, e-mail: dev-unsubscribe (AT) subversion (DOT) tigris.org
For additional commands, e-mail: dev-help (AT) subversion (DOT) tigris.org

Tue, 2005-07-19 at 20:08 -0700, Brian Holmes wrote:
#define svn_repos_write_errorlog(repos, log_level, message) \
do { \
if ((repos)->error_log->level <= log_level) \
svn_log_write((repos)->error_log, log_level, message) \
} while(0);

The value of the macro here is huge. The macro allows us to:
* enforce a constant method of logging that checks the log level
before calling the function
* prevents us from processing the 'message' parameter when
unnecessary.
* makes our code much more readable.
* makes logging simple from a programmer perspective while keeping
things efficient.

You've managed to say two things in four ways, and one of them isn't
true. Because the macro sacrifices varargs, our code looks less
readable:

SVN_REPS_LG(repos, log_level, apr_psprintf(pool, fmt, args), pool)

is less readable than

svn_repos_log(repos, log_level, pool, fmt, args)

Your macro also requires us to expose the internals of svn_repos_t in
the ABI; svn_repos_t is currently an opaque type.

* we can easily make changes to logic by changing the macro (like
checking if repos or repos->error_log is null before calling the
function) or we could completely (and possibly selectively) remove the
logging code altogether.

We can easily make changes to the logic of the function too. Macros are
not superior to functions as a means of abstraction.

I'm not sure what to say about the var args. It is true that using a
macro will not allow us to use var args cleanly. However, do we
really need to use varargs and does it outweight my purported
benefits?

For the kind of logging we will actually be adding (and so far, no one
has had a *single* counterexample to this), the purported benefits allow
us to save a few cycles before executing an operation such as "checkout"
which will take millions upon millions of cycles to execute.

Compared to that, the readability of a varargs function is orders of
magnitude more important.

To unsubscribe, e-mail: dev-unsubscribe (AT) subversion (DOT) tigris.org
For additional commands, e-mail: dev-help (AT) subversion (DOT) tigris.org

Greg Hudson <ghudson (AT) MIT (DOT) EDUwrites:
For the kind of logging we will actually be adding (and so far, no one
has had a *single* counterexample to this), the purported benefits allow
us to save a few cycles before executing an operation such as "checkout"
which will take millions upon millions of cycles to execute.

Compared to that, the readability of a varargs function is orders of
magnitude more important.

I'd like to suggest that we resolve this debate in favor of the
function, not the macro. Here's why:

The penalties of using a macro are definite. Greg has listed them
ably, no one need wonder what they are. If we use a macro, we know
for sure we will suffer these penalties -- however minor they may be,
we *will* experience them.

The penalties of using a function are not definite. They are
tentative predictions, based on Brane's (and perhaps others')
experiences with other programs. Real-world experience is valuable,
but there are two different ways to take advantage of it:

1) We can decide we're likely to have the same problems, and
go with the macro, or

2) We can remember that these problems are a possibility, and keep
a watchful eye for them when profiling and when receiving
reports of performance problems. If the function calls ever
become a problem in real life, we switch to the macro system.
This would be a trivial coding effort, nor would the old code be
wasted, since most of the work of writing logging calls is
choosing where to put them and what information to log.

Brane's telling us something we need to know, but that doesn't mean we
must assume the worst will happen. It's enough that he helps us be
aware that the worst *can* happen.

So: can we please start with the function-based system, and stay away
from pink.bikeshed.com? :-)
-Karl

To unsubscribe, e-mail: dev-unsubscribe (AT) subversion (DOT) tigris.org
For additional commands, e-mail: dev-help (AT) subversion (DOT) tigris.org

7/19/05, Greg Hudson <ghudson (AT) mit (DOT) eduwrote:

Tue, 2005-07-19 at 20:08 -0700, Brian Holmes wrote:
#define svn_repos_write_errorlog(repos, log_level, message) \
do { \
if ((repos)->error_log->level <= log_level) \
svn_log_write((repos)->error_log, log_level, message) \
} while(0);

The value of the macro here is huge. The macro allows us to:
* enforce a constant method of logging that checks the log level
before calling the function
* prevents us from processing the 'message' parameter when
unnecessary.
* makes our code much more readable.
* makes logging simple from a programmer perspective while keeping
things efficient.

You've managed to say two things in four ways, and one of them isn't
true. Because the macro sacrifices varargs, our code looks less
readable:

SVN_REPS_LG(repos, log_level, apr_psprintf(pool, fmt, args), pool)

is less readable than

svn_repos_log(repos, log_level, pool, fmt, args)

Your macro also requires us to expose the internals of svn_repos_t in
the ABI; svn_repos_t is currently an opaque type.

Yeah, I stretched that one a bit. :) I was not aware that svn_repos_t was
opaque however, and that does change my view on things.

* we can easily make changes to logic by changing the macro (like
checking if repos or repos->error_log is null before calling the
function) or we could completely (and possibly selectively) remove the
logging code altogether.

We can easily make changes to the logic of the function too. Macros are
not superior to functions as a means of abstraction.

They are superior only in the sense that we can put logic before the
function call and thus "save a few cycles."

I'm not sure what to say about the var args. It is true that using a
macro will not allow us to use var args cleanly. However, do we
really need to use varargs and does it outweight my purported
benefits?

For the kind of logging we will actually be adding (and so far, no one
has had a *single* counterexample to this), the purported benefits allow
us to save a few cycles before executing an operation such as "checkout"
which will take millions upon millions of cycles to execute.

True that svn_repos may not use the logging extensively, at least not for
basic access or error messages, but if we started using it for debug tracing
it could add up. I was making the assumption that we might actually say

svn_repos_log(repos, DEBUG_TRACE, pool, fmt, args);

at which point if they were in low level functions being called hundreds of
thousands of times they would certainly chew up a lot of time.

Compared to that, the readability of a varargs function is orders of
magnitude more important.

With your example, I have to agree that varargs is much easier to read.

Given the varargs debate, and more importantly, the opaqueness of
svn_repos_t, it seems prudent to use a function rather than a macro.
- Brian