Reduce overhead incurred by enabling debug output.

[ywkaras]

Setting proxy.config.diags.debug.enabled to 3 enables most core debug output (whose tag matches the debug
regex), and plugin debug output from the new API macro TSDbg(). Setting it to 1 enables all (matching) debug
output, but with the previous high overhead.

Note that enabling a large qualtity of debug output will still have a big impact on performance.

[ywkaras]

Replaces #7452 .

[ywkaras]

Performance Testing

Test server: Intel Xeon CPU ES-2683 v4 @ 2.10GHz, 64 logical CPU cores.

Baseline build, master commit a5a8523

records.config:

CONFIG proxy.config.url_remap.remap_required INT 0
CONFIG proxy.config.http.cache.required_headers INT 0
CONFIG proxy.config.http.push_method_enabled INT 1
CONFIG proxy.config.http.server_ports STRING 8080 8081
CONFIG proxy.config.diags.debug.enabled INT 0
CONFIG proxy.config.diags.debug.tags STRING does_not_match_anything

remap.config:

map http://localhost:8081 http://fakehost

Command to start TS:
TS_ROOT=$PWD LD_LIBRARY_PATH=$PWD/lib bin/traffic_server &

I ran this script to create the object /fake in the cache:

# Create an object in TS cache by sending a PUSH request.  First param is TS TCP port to send request to
# (default 8080).  Second param is size in bytes (default 1K).

if [[ "$1" != "" ]] ; then
    PORT=$1
else
    PORT=8080
fi

if [[ "$2" != "" ]] ; then
    BYTES=$2
else
    BYTES=1024
fi

EXE=$(mktemp)

cc -x c -o $EXE - << THE_END

#include <stdio.h>
#include <stdlib.h>
#include <stdint.h>
#include <inttypes.h>

int
main(int n_arg, char const *const *arg)
{
  int64_t data_count;
  int toggle = 0;
  int c = 'a', hdr_count;
  char buf[200];

  if ((n_arg != 2) || ((data_count = atoi(arg[1])) <= 0)) {
    fprintf(stderr, "size of object must be greater than 0\n");
    return 1;
  }

  hdr_count = snprintf(buf, sizeof(buf),
                       "HTTP/1.1 200 OK\r\n"
                       "Content-Type: text/plain\r\n"
                       "Content-Length: %" PRId64 "\r\n"
                       "\r\n",
                       data_count);

  if (hdr_count <= 0) {
    fprintf(stderr, "INTERNAL ERROR\n");
    return 1;
  }

  if (printf("PUSH http://fakehost/fake HTTP/1.1\r\n"
             "Content-Length: %" PRId64 "\r\n"
             "\r\n%s",
             hdr_count + data_count, buf) <= 0) {
    fprintf(stderr, "error writing standard output\n");
    return 1;
  }

  while (--data_count) {
    if (putchar(c) != c) {
      fprintf(stderr, "error writing standard output\n");
      return 1;
    }
    if (c == '\n') {
      c = 'a';
    } else if (toggle) {
      if (c == 'z') {
        c = '\n';
      } else {
        ++c;
      }
      toggle = 0;
    } else {
      toggle = 1;
    }
  }

  if (putchar('\n') != '\n') {
    fprintf(stderr, "error writing standard output\n");
    return 1;
  }

  if (fflush(stdout) != 0) {
    fprintf(stderr, "error writing standard output\n");
    return 1;
  }

  return 0;
}
THE_END

$EXE $BYTES | nc localhost $PORT

rm -f $EXE

Traffic generation command (for all tests):
h2load --h1 -t 64 -D 60 -c 512 http://localhost:8081/fake

finished in 60.08s, 244096.15 req/s, 275.16MB/s
requests: 14645769 total, 14646281 started, 14645769 done, 14645769 succeeded, 0 failed, 0 errored, 0 timeout
status codes: 14645769 2xx, 0 3xx, 0 4xx, 0 5xx
traffic: 16.12GB (17311298958) total, 1.57GB (1684276200) headers (space savings 0.00%), 13.97GB (14997381120) data
                     min         max         mean         sd        +/- sd
time for request:       48us    366.16ms      2.05ms     11.35ms    97.18%
time for connect:       56us     25.50ms       962us      3.88ms    97.46%
time to 1st byte:      329us    179.31ms     13.71ms     21.73ms    88.48%
req/s           :     443.05      506.56      476.75       13.49    73.44%

Changed debug.enabled to 1:

finished in 60.08s, 12595.35 req/s, 14.21MB/s
requests: 755721 total, 756233 started, 755721 done, 755721 succeeded, 0 failed, 0 errored, 0 timeout
status codes: 755721 2xx, 0 3xx, 0 4xx, 0 5xx
traffic: 852.60MB (894017943) total, 83.60MB (87664680) headers (space savings 0.00%), 738.02MB (773867520) data
                     min         max         mean         sd        +/- sd
time for request:       82us    706.70ms     40.61ms     56.02ms    85.84%
time for connect:       51us     16.27ms       569us      1.96ms    98.44%
time to 1st byte:     1.21ms    495.01ms     90.48ms     78.03ms    68.36%

Switched to build with the changes in this PR, https://github.com/ywkaras/trafficserver/tree/FasterDiags2_20210409, set debug.enaabled to 0:

finished in 60.07s, 253010.88 req/s, 285.20MB/s
requests: 15180653 total, 15181165 started, 15180653 done, 15180653 succeeded, 0 failed, 0 errored, 0 timeout
status codes: 15180653 2xx, 0 3xx, 0 4xx, 0 5xx
traffic: 16.71GB (17943531846) total, 1.63GB (1745781190) headers (space savings 0.00%), 14.48GB (15545042944) data
                     min         max         mean         sd        +/- sd
time for request:       49us    356.82ms      2.02ms     11.19ms    97.17%
time for connect:       52us       996us       332us       184us    64.65%
time to 1st byte:      355us    160.75ms      8.53ms     17.47ms    91.80%
req/s           :     393.28      598.30      494.16       68.07    58.98%

Changed debug.enabled to 1:

finished in 60.08s, 235457.07 req/s, 265.19MB/s
requests: 14127424 total, 14127936 started, 14127424 done, 14127424 succeeded, 0 failed, 0 errored, 0 timeout
status codes: 14127424 2xx, 0 3xx, 0 4xx, 0 5xx
traffic: 15.54GB (16684487744) total, 1.50GB (1610532606) headers (space savings 0.00%), 13.47GB (14466538496) data
                     min         max         mean         sd        +/- sd
time for request:       51us    387.38ms      2.19ms     11.95ms    97.04%
time for connect:       52us     15.86ms       565us      1.62ms    98.24%
time to 1st byte:      332us    193.80ms     15.61ms     22.70ms    91.41%
req/s           :     424.37      496.46      459.87       14.61    72.07%

Changed debug.enabled to 3:

finished in 60.18s, 285280.92 req/s, 321.85MB/s
requests: 17116855 total, 17117367 started, 17116855 done, 17116855 succeeded, 0 failed, 0 errored, 0 timeout
status codes: 17116855 2xx, 0 3xx, 0 4xx, 0 5xx
traffic: 18.86GB (20249239465) total, 1.85GB (1985567128) headers (space savings 0.00%), 16.32GB (17527764992) data
                     min         max         mean         sd        +/- sd
time for request:       48us    314.86ms      1.79ms      9.29ms    97.20%
time for connect:       53us    127.69ms      5.54ms     25.00ms    95.90%
time to 1st byte:      271us    190.07ms     15.85ms     29.97ms    91.60%
req/s           :     509.30      585.57      557.19       14.56    68.95%

It seems impossible that performance is better with debug.enabled set to 3 versus 0.

[ywkaras]

Needed this change to fix a Clang Analyzer error.

[ywkaras]

The inclusion of ts.h in DiagsTypes.h required this change.

[ywkaras]

@calavera after I rebase this could you review it or ask someone else at Linkedin to look at it?

[bryancall]

@ywkaras is going to fix the conflict and we are going to merge. We need another PR to clean up the APIs both internally and externally.

[zwoop]

Hmmm, so I don't quite understand this. Is the point here that I can do "traffic_server -T http" and it has no cost vs not turning on -T ? Or is the point that having an obscure debug tag enabled, which rarely (if ever) triggers, has no cost?

And why do we need a new TSDbg() if the changes are sufficient for the existing TSDebug() ?

[zwoop]

I'm overall ok with this, it's a good approach. I don't mind those global registered control variables (static), and I'm pleased to see a consistent naming on them.

I'm ok with this approach, with two conditions:

1. We mark TSDebug() (the public API) as deprecated for 10.0.0, and we delete TSDebug() in 11.0.
2. We (and with we, I mean @ywkaras ) promise to finish the core refactoring, eliminating all Debug() calls in the core. This doesn't have to happen for 10.0.0, but I will be disappointed if it's not complete before 11.0.0.

In addition, this may be a good starting point for also documenting and normalizing the tag naming conventions for a future 10.0.0 and/or 11.0.0 release.

[zwoop]

I feel reasonably strongly that for 10.0.0, we should:

1. Mark TSDebug() deprecated here (such that it gives compiler warnings)
2. Change all plugins in the core to use TSDbg() (to avoid warnings from # 1.

[zwoop]

I think for core use of Dbg(), we should assert, or at least warn when there is a duplication of a control (i.e. two or more versions of a debug label).

[ywkaras]

So @zwoop what's the short list of changes to get this merged? While we're young. Or alive.

[ywkaras]

OK @zwoop it's soup.

[ywkaras]

@zwoop did you want to request changes, can you write up the specifics? Would you rather someone else reviewed it?

I stopped pushing new commits to fix merge conflicts, as I don't want to put more effort into it if it's pocket vetoed. That's why it's currently marked as draft.

[bryancall]

[approve ci]

[bryancall]

[approve ci]

[ywkaras]

@bryancall No point in resolving CI issues with this for now, the problem is getting it reviewed properly.