Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 5 additions & 1 deletion doc/admin-guide/files/records.config.en.rst
Original file line number Diff line number Diff line change
Expand Up @@ -3327,6 +3327,10 @@ Diagnostic Logging Configuration

When set to 2, interprets the :ts:cv:`proxy.config.diags.debug.client_ip` setting determine whether diagnostic messages are logged.

When set to 3, enables logging for diagnostic messages whose log level is `diag` or `debug`, except those
output by deprecated functions such as `TSDebug()` and `TSDebugSpecific()`. Using the value 3 will have less
of a negative impact on proxy throughput than using the value 1.

.. ts:cv:: CONFIG proxy.config.diags.debug.client_ip STRING NULL

if :ts:cv:`proxy.config.diags.debug.enabled` is set to 2, this value is tested against the source IP of the incoming connection. If there is a match, all the diagnostic messages for that connection and the related outgoing connection will be logged.
Expand All @@ -3349,7 +3353,7 @@ Diagnostic Logging Configuration
ssl TLS termination and certificate processing
============ =====================================================

|TS| plugins will typically log debug messages using the :c:func:`TSDebug`
|TS| plugins will typically log debug messages using the :c:func:`TSDbg`
API, passing the plugin name as the debug tag.

.. ts:cv:: CONFIG proxy.config.diags.debug.throttling_interval_msec INT 0
Expand Down
21 changes: 17 additions & 4 deletions doc/developer-guide/api/functions/TSDebug.en.rst
Original file line number Diff line number Diff line change
Expand Up @@ -18,8 +18,8 @@

.. default-domain:: c

TSDebug
*******
TSDbg
*****

Traffic Server Debugging APIs.

Expand All @@ -37,7 +37,11 @@ Synopsis
.. function:: void TSFatal(const char * format, ...)
.. function:: void TSAlert(const char * format, ...)
.. function:: void TSEmergency(const char * format, ...)
.. type:: TSDbgCtl
.. function:: void TSDbg(const TSDbgCtl * ctlptr, const char * format, ...)
.. function:: const TSDbgCtl * TSDbgCtlCreate(const char * tag)
.. function:: void TSDebug(const char * tag, const char * format, ...)
.. function:: int TSIsDbgCtlSet(const TSDbgCtl * ctlptr)
.. function:: int TSIsDebugTagSet(const char * tag)
.. function:: void TSDebugSpecific(int debug_flag, const char * tag, const char * format, ...)
.. function:: void TSHttpTxnDebugSet(TSHttpTxn txnp, int on)
Expand Down Expand Up @@ -76,10 +80,19 @@ Traffic Server, Traffic Manager, AuTest, CI, and your log monitoring service/das
trafficserver.out
=================

:func:`TSDebug` logs the debug message only if the given debug :arg:`tag` is enabled.
:func:`TSDbg` logs the debug message only if the given debug control pointed to by
:arg:`ctlptr` is enabled. It writes output to the Traffic Server debug log through stderr.

:func:`TSDbgCtlCreate` creates a debug control, associated with the
debug :arg:`tag`, and returns a const pointer to it.

:func:`TSIsDbgCtlSet` returns non-zero if the given debug control, pointed to by :arg:`ctlptr`, is
enabled.

:func:`TSDebug` (deprecated) logs the debug message only if the given debug :arg:`tag` is enabled.
It writes output to the Traffic Server debug log through stderr.

:func:`TSIsDebugTagSet` returns non-zero if the given debug :arg:`tag` is
:func:`TSIsDebugTagSet` (deprecated) returns non-zero if the given debug :arg:`tag` is
enabled.

In debug mode, :macro:`TSAssert` Traffic Server to prints the file
Expand Down
53 changes: 45 additions & 8 deletions doc/developer-guide/debugging/debug-tags.en.rst
Original file line number Diff line number Diff line change
Expand Up @@ -22,16 +22,34 @@
Debug Tags
**********

Use the API
``void TSDebug (const char *tag, const char *format_str, ...)`` to add
traces in your plugin. In this API:
Use the API macro
``TSDbg(ctlptr, const char *format_str, ...)`` to add
traces in your plugin. In this macro:

- ``ctlptr`` is the Traffic Server parameter that enables Traffic Server
to print out ``format_str``. It is returned by ``TSDbgCtlCreate()``.

- ``...`` are variables for ``format_str`` in the standard ``printf``
style.

``void TSDbgCtlCreate (const char *tag)`` returns a (const) pointer to
``TSDbgCtl``. The ``TSDbgCtl`` control is enabled when debug output is
enabled globally by configuaration, and ``tag`` matches a configured
regular expression.

The deprecated API
``void TSDebug (const char *tag, const char *format_str, ...)`` also
outputs traces. In this API:

- ``tag`` is the Traffic Server parameter that enables Traffic Server
to print out *``format_str``*
to print out ``format_str``

- ``...`` are variables for *``format_str``* in the standard ``printf``
- ``...`` are variables for ``format_str`` in the standard ``printf``
style.

Use of ``TSDebug()`` causes trace output to have a more negative impact
on proxy throughput.

Run Traffic Server with the ``-Ttag`` option. For example, if the tag is
``my-plugin``, then the debug output goes to ``traffic.out.``\ See
below:
Expand All @@ -40,21 +58,30 @@ below:

traffic_server -T"my-plugin"

Set the following variables in :file:`records.config` (in the Traffic Server
Sets the following variables in :file:`records.config` (in the Traffic Server
``config`` directory):

::

CONFIG proxy.config.diags.debug.enabled INT 1
CONFIG proxy.config.diags.debug.tags STRING debug-tag-name

(Performance will be better if ``enabled`` is set to 3 rather than 1, but,
using 3, output from ``TSDebug()`` will not be enabled, only from ``TSDbg()``.)
In this case, debug output goes to ``traffic.out``.

Example:

.. code-block:: c

TSDebug ("my-plugin", "Starting my-plugin at %d", the_time);
static TSDbgCtl const *my_dbg_ctl; // Non-local variable.
...
my_dbg_ctl = TSDbgCtlCreate("my-plugin"); // In TSPluginInit() or TSRemapInit().
...
TSDbg(my_dbg_ctl, "Starting my-plugin at %d", the_time);
...
TSDbg(my_dbg_ctl, "Later on in my-plugin");


The statement ``"Starting my-plugin at <time>"`` appears whenever you
run Traffic Server with the ``my-plugin`` tag:
Expand All @@ -63,6 +90,16 @@ run Traffic Server with the ``my-plugin`` tag:

traffic_server -T"my-plugin"

If your plugin is a C++ plugin, the above example can be written as:

.. code-block:: cpp

static auto my_dbg_ctl = TSDbgCtlCreate("my-plugin"); // Non-local variable.
...
TSDbg(my_dbg_ctl, "Starting my-plugin at %d", the_time);
...
TSDbg(my_dbg_ctl, "Later on in my-plugin");

Other Useful Internal Debug Tags
================================

Expand All @@ -71,7 +108,7 @@ internal debugging purposes. These can also be used to follow Traffic
Server behavior for testing and analysis.

The debug tag setting (``-T`` and ``proxy.config.diags.debug.tags``) is a
anchored regular expression against which the tag for a specific debug
anchored regular expression (PCRE) against which the tag for a specific debug
message is matched. This means the value "http" matches debug messages
with the tag "http" but also "http\_seq" and "http\_trans". If you want
multiple tags then use a pipe symbol to separate the tags. For example
Expand Down
17 changes: 9 additions & 8 deletions doc/developer-guide/plugins/plugin-interfaces.en.rst
Original file line number Diff line number Diff line change
Expand Up @@ -122,14 +122,15 @@ The thread functions are listed below:
Debugging Functions
===================

- :c:func:`TSDebug`
prints out a formatted statement if you are running Traffic Server in
debug mode.

- :c:func:`TSIsDebugTagSet`
checks to see if a debug tag is set. If the debug tag is set, then
Traffic Server prints out all debug statements associated with the
tag.
- :c:func:`TSDbg`
(replaces deprecated :c:func:`TSDebug`) prints out a formatted
statement if you are running Traffic Server in debug mode.

- :c:func:`TSIsDbgCtlSet`
(replaces deprecated :c:func:`TSIsDebugTagSet`)
checks to see if a debug control (associated with a debug tag) is
set. If the debug tag is set, then Traffic Server prints out all
debug statements associated with the control.

- :c:func:`TSError`
prints error messages to Traffic Server's error log
Expand Down
5 changes: 5 additions & 0 deletions include/ts/apidefs.h.in
Original file line number Diff line number Diff line change
Expand Up @@ -1070,6 +1070,11 @@ typedef struct TSHttpConnectOptions_s {
TSIOBufferWaterMark buffer_water_mark;
} TSHttpConnectOptions;

typedef struct TSDbgCtl_s {
char volatile on; // Flag
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The way this volatile declaration is used is undefined behavior. See usage for volatile after C++11. particularly:

This makes volatile objects suitable for communication with a signal handler, but not with another thread of execution, see std::memory_order). Any attempt to refer to a volatile object through a glvalue of non-volatile type (e.g. through a reference or pointer to non-volatile type) results in undefined behavior.

If you want to guarantee that changes are seen immediately in another thread, you will need to use some memory ordering mechanism. Otherwise, other threads will see changes the next time that memory is read.

I tested this without volatile and it still adjusts the debug that are printed.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The reality is that ATS often relies on de facto portability, rather than portability guaranteed by the Standard.

I guess memory ordering has been added to straight C, but I don't know the specifics, I'll have to research this. The point of the volatile is to emphasize that that the on flag should not be register cached. But it seems implausible the compiler could do that indefinitely anyway.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's correct that (when using Debug() instead of Dbg() ) there's a significant increase in loaded data segment size, But, it's a delta on top of the high resource use of trace output even with the old design. Which seems worthwhile, to make tracing usable in production.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree this is a worthwhile trade off for performant debugging! It's good stuff.

I also think that in this case, any changes to on values will be seen "soon enough" by other threads and that volatile just isn't necessary here(especially since its accessed through a non-volatile pointer).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Although it's unlikely, this code illustrates the sort of optimization that could happen to a Debug statement in a loop, if we don't do something to prevent the compiler from register-caching the 'on' flag: https://godbolt.org/z/r4K9TP1qW

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The alternate to simply relying on volatile would be to use atomic_load_explicit() with relaxed memory order. But that would mean we'd have to require plugins to be build with C11 support, which I don't think we've done up till now.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note that the Standard says that the behavior of reinterpret_cast is undefined, but ATS uses it over 1,400 times.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is closer to (but still not quite) the situation we have here. We are accessing a volatile through a (non-volatile) static pointer. The compiler must read from memory at least one time when the containing function is called. For the non-volatile case, the compiler can then assume the value won't change until another function is called or the original function is called again. This is what I meant by it will be re-read "soon enough".

All that said, if you are happier with the volatile qualifier and no-one else objects, I'm not overly concerned about it.

char const *tag;
} TSDbgCtl;

/* --------------------------------------------------------------------------
Init */

Expand Down
31 changes: 30 additions & 1 deletion include/ts/ts.h
Original file line number Diff line number Diff line change
Expand Up @@ -2190,11 +2190,40 @@ tsapi void TSDebug(const char *tag, const char *format_str, ...) TS_PRINTFLIKE(2
@param ... Format arguments.
*/
tsapi void TSDebugSpecific(int debug_flag, const char *tag, const char *format_str, ...) TS_PRINTFLIKE(3, 4);
extern int diags_on_for_plugins;
extern int diags_on_for_plugins; /* Do not use directly. */
#define TSDEBUG \
if (diags_on_for_plugins) \
TSDebug

extern char ts_new_debug_on_flag_; /* Do not use directly. */

#define TSIsDbgCtlSet(ctlp__) (ts_new_debug_on_flag_ && ctlp__->on)

/**
Output a debug line if the debug output control is turned on.

@param ctlp pointer to TSDbgCtl, returned by TSDbgCtlCreate().
@param ... Format string and (optional) arguments.
*/
#define TSDbg(ctlp, ...) \
do { \
if (TSIsDbgCtlSet(ctlp)) { \
_TSDbg(ctlp->tag, __VA_ARGS__); \
} \
} while (0)

/**
Return a pointer for use with TSDbg(). For good performance,
this should be called in TSPluginInit() or TSRemapInit(), or in
static initialization in C++ (with the result stored in a
static pointer).

@param tag Debug tag for the control.
*/
tsapi TSDbgCtl const *TSDbgCtlCreate(char const *tag);

void _TSDbg(const char *tag, const char *format_str, ...) TS_PRINTFLIKE(2, 3); /* Not for direct use. */

/* --------------------------------------------------------------------------
logging api */

Expand Down
56 changes: 56 additions & 0 deletions include/tscore/DbgCtl.h
Original file line number Diff line number Diff line change
@@ -0,0 +1,56 @@
/** @file
DbgCtl class header file.
@section license License
Licensed to the Apache Software Foundation (ASF) under one
or more contributor license agreements. See the NOTICE file
distributed with this work for additional information
regarding copyright ownership. The ASF licenses this file
to you under the Apache License, Version 2.0 (the
"License"); you may not use this file except in compliance
with the License. You may obtain a copy of the License at
http://www.apache.org/licenses/LICENSE-2.0
Unless required by applicable law or agreed to in writing, software
distributed under the License is distributed on an "AS IS" BASIS,
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
See the License for the specific language governing permissions and
limitations under the License.
*/

#pragma once

#include <ts/ts.h>

// For use with TSDbg().
//
class DbgCtl
{
public:
// Tag is a debug tag. Debug output associated with this control will be output when debug output
// is enabled globally, and the tag matches the configured debug tag regular expression.
//
DbgCtl(char const *tag) : _ptr(_get_ptr(tag)) {}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could call TSDbgCtlCreate instead of _get_ptr directly to get the asserts

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You mean checking that tag is not null? I don't think we normally call TS API functions from core TS.


TSDbgCtl const *
ptr() const
{
return _ptr;
}

// Call this when the compiled regex to enable tags may have changed.
//
static void update();

private:
TSDbgCtl const *const _ptr;

static const TSDbgCtl *_get_ptr(char const *tag);

class _RegistryAccessor;

friend TSDbgCtl const *TSDbgCtlCreate(char const *tag);
};
Loading