Stop writing a few hundred log lines per request
Every neighbourhood request printed one line per window position, one per
vocabulary lookup, the whole JSON of a similar profile and the comings and
goings of the worker threads. Together with the crawler traffic that came
to about a million lines a day on corpora.ids-mannheim.de, which is what
filled the log partition of the machine.
Those diagnostics are behind DEREKOVECS_DEBUG now, and the per request
narration of the perl side, which repeated what the access log line of the
same request already says, is logged at debug level. What is left in the
default configuration is one line per request, plus the user agent of a
request that was turned away as a crawler.
Startup messages, the model mapping and error messages are untouched.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Change-Id: I4059a1db5ba59a59da6177225c6f66ff53ddcaec
diff --git a/Changelog.md b/Changelog.md
index 652474b..0657d12 100644
--- a/Changelog.md
+++ b/Changelog.md
@@ -14,6 +14,16 @@
- `robots.txt` is served at every path, for installations that own their host
name; behind a proxy that mounts derekovecs below a path, the site wide
robots.txt still has to say it
+- the per request diagnostics of the vector code are off unless
+ `DEREKOVECS_DEBUG` is set. Every neighbourhood request wrote a few hundred
+ lines - one per window position, one per vocabulary lookup, the whole JSON of
+ a similar profile - which came to a million lines a day on
+ corpora.ids-mannheim.de and filled the log partition of the machine. Startup
+ and error messages are unaffected
+- the per request narration of the perl side - which word is being looked up,
+ which result comes from a cache, which static file was fetched - is logged at
+ debug level now. It repeated what the access log line of the same request
+ already says
## [0.96] - 2026-07-31
diff --git a/README.md b/README.md
index 346c4ea..54371a5 100644
--- a/README.md
+++ b/README.md
@@ -119,6 +119,27 @@
That is a request, not a barrier - it is obeyed by the crawlers that care, and
the `403` above is what stops the rest.
+### Logging
+
+The server logs one line per request. The per request diagnostics of the
+vector code - one line per window position, one per vocabulary lookup, the
+whole JSON of a similar profile - are off by default; a single neighbourhood
+request writes a few hundred of them, which is a million lines a day on a busy
+instance. Set `DEREKOVECS_DEBUG=1` in the environment to get them back:
+
+```bash
+DEREKOVECS_DEBUG=1 MOJO_CONFIG=$(pwd)/example.conf morbo script/derekovecs-server
+```
+
+Startup messages, the memory mapping of the model and error messages are not
+affected by it.
+
+The perl side logs one line per request. What it used to say in addition -
+which word is being looked up, which result came from a cache - is logged at
+debug level and can be turned on with `MOJO_LOG_LEVEL=debug`. Requests that are
+turned away as crawlers are logged with their user agent, so that the list can
+be checked against what actually arrives.
+
## Web Service API
In addition to the web user interface, derekovecs also provides a web api which is however still very unsystematic and **not stable**. To figure out the meaning of still undocumented result components, have a look at the table head mouse-overs in the GUI or at the source code around [here](https://korap.ids-mannheim.de/gerrit/plugins/gitiles/ids-kl/derekovecs/+/refs/heads/master/templates/index.html.ep#684).
diff --git a/lib/IDS/DeReKoVecs/Read.pm b/lib/IDS/DeReKoVecs/Read.pm
index f75ca90..0b396ec 100644
--- a/lib/IDS/DeReKoVecs/Read.pm
+++ b/lib/IDS/DeReKoVecs/Read.pm
@@ -89,19 +89,19 @@
my $pipe;
if($compare_to ne "") {
- $c->app->log->info("comparing syn neighbours to: $compare_to/getClassicCollocators?w=$word");
+ $c->app->log->debug("comparing syn neighbours to: $compare_to/getClassicCollocators?w=$word");
open $pipe, "lwp-request $compare_to/getClassicCollocators?w=$word |";
}
my $collocators = $opt_C ? undef : $cccache->get($word);
if(!defined $collocators) {
- $c->app->log->info("Getting classic collocates of $word.");
+ $c->app->log->debug("Getting classic collocates of $word.");
$collocators = getClassicCollocators($word);
$collocators =~ s/:(-?)(nan|inf)/:"${1}${2}"/g;
$collocators =~ s/"""/"\\""/g;
$cccache->set($word => $collocators) unless $opt_C;
} else {
- $c->app->log->info("Getting classic collocates for $word from cache.");
+ $c->app->log->debug("Getting classic collocates for $word from cache.");
}
if(defined($pipe)) {
@@ -145,7 +145,7 @@
$profiles = getSimilarProfiles($word);
$spcache->set($word => $profiles) unless $opt_C;
} else {
- $c->app->log->info("Getting similar profiles for $word from cache:");
+ $c->app->log->debug("Getting similar profiles for $word from cache:");
}
return $profiles;
}
diff --git a/lib/IDS/DeReKoVecs/derekovecs-server.c b/lib/IDS/DeReKoVecs/derekovecs-server.c
index 56e037c..b1aa341 100644
--- a/lib/IDS/DeReKoVecs/derekovecs-server.c
+++ b/lib/IDS/DeReKoVecs/derekovecs-server.c
@@ -19,6 +19,26 @@
#define MAX_EXP 6
#define MIN_RESP 0.50
+/* Per request diagnostics. Every neighbourhood request used to write a few
+ hundred lines - one per window position, one per vocabulary lookup, the
+ whole JSON of a similar profile - and a busy instance turned that into a
+ million lines a day, which is what filled the log partition of the
+ production machine. They are off unless DEREKOVECS_DEBUG is set to
+ something other than 0 or the empty string. Startup messages and error
+ messages are not affected. */
+static int derekovecs_debug(void) {
+ static int enabled = -1;
+ if (enabled < 0) {
+ const char *e = getenv("DEREKOVECS_DEBUG");
+ enabled = (e && *e && strcmp(e, "0") != 0) ? 1 : 0;
+ }
+ return enabled;
+}
+
+#define DEBUG_PRINTF(...) do { if (derekovecs_debug()) printf(__VA_ARGS__); } while (0)
+#define DEBUG_EPRINTF(...) do { if (derekovecs_debug()) fprintf(stderr, __VA_ARGS__); } while (0)
+#define DEBUG_FFLUSH() do { if (derekovecs_debug()) fflush(stdout); } while (0)
+
//the thread function
void *connection_handler(void *);
@@ -422,7 +442,7 @@
if (a >= window)
a++;
wpos_sum = 0;
- printf("window pos: %ld\n", a);
+ DEBUG_PRINTF("window pos: %ld\n", a);
if (a != window) {
max_f = -1;
window_offset = a * size;
@@ -458,8 +478,8 @@
worstbest = best[N - 1].activation;
}
}
- printf("%ld %.2f\n", max_target, max_f);
- printf("%s (%.2f) ", &vocab[max_target * max_w], max_f);
+ DEBUG_PRINTF("%ld %.2f\n", max_target, max_f);
+ DEBUG_PRINTF("%s (%.2f) ", &vocab[max_target * max_w], max_f);
if (max_f > maxmax_f) {
maxmax_f = max_f;
maxmax_target = max_target;
@@ -468,7 +488,7 @@
if (best[b].position == window - a)
best[b].cprobability = best[b].activation / wpos_sum;
} else {
- printf("\x1b[1m%s\x1b[0m ", &vocab[d * max_w]);
+ DEBUG_PRINTF("\x1b[1m%s\x1b[0m ", &vocab[d * max_w]);
}
pars->window_sums[a] = wpos_sum;
}
@@ -555,11 +575,11 @@
buffer[0] = '[';
buffer[1] = 0;
if (node < 0 || node >= sprofiles_qty) {
- printf("Not available in precomputed profile\n");
+ DEBUG_PRINTF("Not available in precomputed profile\n");
return newSVpv("[{\"w\":\"not available\", \"v\":0}]\n", 0);
}
- printf("******* %s ******\n", &vocab[max_w * node]);
+ DEBUG_PRINTF("******* %s ******\n", &vocab[max_w * node]);
for (i = 0; i < 100 && i < sprofiles[node].len; i++) {
sprintf(pair_buffer, "{\"w\":\"%s\", \"v\":%f},", &vocab[max_w * (sprofiles[node].nbr[i].index)], sprofiles[node].nbr[i].value);
@@ -570,7 +590,7 @@
else
strcat(buffer, "]");
strcat(buffer, "\n");
- printf("%s", buffer);
+ DEBUG_PRINTF("%s", buffer);
return newSVpv(buffer, 0);
}
@@ -623,10 +643,10 @@
if (b == words) b = -1;
wl->wordi[a] = b;
if (b == -1) {
- fprintf(stderr, "Out of dictionary word!\n");
+ DEBUG_EPRINTF("Out of dictionary word!\n");
cn--;
} else {
- fprintf(stderr, "Word: \"%s\" Position in vocabulary: %lld\n", &vocab[wl->wordi[a] * max_w], wl->wordi[a]);
+ DEBUG_EPRINTF("Word: \"%s\" Position in vocabulary: %lld\n", &vocab[wl->wordi[a] * max_w], wl->wordi[a]);
}
}
wl->length = cn;
@@ -665,7 +685,7 @@
if (result != NULL)
return newSVpv(result, 0);
- printf("Looking for biggest distances between main and merged vectors ...\n");
+ DEBUG_PRINTF("Looking for biggest distances between main and merged vectors ...\n");
collocator *best;
best = malloc(N * sizeof(collocator));
memset(best, 0, N * sizeof(collocator));
@@ -720,7 +740,7 @@
res = -1;
else {
res = cos_similarity(a->wordi[0], b->wordi[0]);
- fprintf(stderr, "a: %lld b: %lld res:%f\n", a->wordi[0], b->wordi[0], res);
+ DEBUG_EPRINTF("a: %lld b: %lld res:%f\n", a->wordi[0], b->wordi[0], res);
}
free(a);
free(b);
@@ -831,8 +851,8 @@
a = posix_memalign((void **)&target_sums, 128, cutoff * sizeof(float));
memset(target_sums, 0, cutoff * sizeof(float));
- printf("Starting %d threads\n", syn_threads);
- fflush(stdout);
+ DEBUG_PRINTF("Starting %d threads\n", syn_threads);
+ DEBUG_FFLUSH();
for (a = 0; a < syn_threads; a++) {
pars[a].cutoff = cutoff;
pars[a].target_sums = target_sums;
@@ -845,11 +865,11 @@
pars[a].upto = a + 1;
pthread_create(&pt[a], NULL, getCollocators, (void *)&pars[a]);
}
- printf("Waiting for syn threads to join\n");
- fflush(stdout);
+ DEBUG_PRINTF("Waiting for syn threads to join\n");
+ DEBUG_FFLUSH();
for (a = 0; a < syn_threads; a++) pthread_join(pt[a], (void *)&syn_nbs[a]);
- printf("Syn threads joint\n");
- fflush(stdout);
+ DEBUG_PRINTF("Syn threads joint\n");
+ DEBUG_FFLUSH();
result = malloc((maxPerPos > 0 ? maxPerPos : 1) * (max_w + 96) * syn_threads + 16);
char *p = (char *) result;
*p = 0;
@@ -926,8 +946,8 @@
a = posix_memalign((void **)&target_sums, 128, cutoff * sizeof(float));
memset(target_sums, 0, cutoff * sizeof(float));
- printf("Starting %d threads for paradigmatic search\n", para_threads);
- fflush(stdout);
+ DEBUG_PRINTF("Starting %d threads for paradigmatic search\n", para_threads);
+ DEBUG_FFLUSH();
for (a = 0; a < para_threads; a++) {
pars[a].cutoff = cutoff;
pars[a].token = st1;
@@ -941,7 +961,7 @@
pars[a].from = merge_words + a * slice;
pars[a].upto = merge_words + ((a + 1) * slice > cutoff ? cutoff : (a + 1) * slice);
}
- printf("From: %ld, Upto: %ld\n", pars[a].from, pars[a].upto);
+ DEBUG_PRINTF("From: %ld, Upto: %ld\n", pars[a].from, pars[a].upto);
pthread_create(&pt[a], NULL, _get_neighbours, (void *)&pars[a]);
}
if (M2) {
@@ -958,11 +978,11 @@
pthread_create(&pt[a + para_threads], NULL, getCollocators, (void *)&pars[a + para_threads]);
}
}
- printf("Waiting for para threads to join\n");
- fflush(stdout);
+ DEBUG_PRINTF("Waiting for para threads to join\n");
+ DEBUG_FFLUSH();
for (a = 0; a < para_threads; a++) pthread_join(pt[a], (void *)¶_nbs[a]);
- printf("Para threads joint\n");
- fflush(stdout);
+ DEBUG_PRINTF("Para threads joint\n");
+ DEBUG_FFLUSH();
/* if(!syn_nbs[0]) */
/* goto end; */
@@ -970,7 +990,7 @@
qsort(best, N * para_threads, sizeof(collocator), cmp_activation);
long long chosen[MAX_NEIGHBOURS];
- printf("N: %d\n", N);
+ DEBUG_PRINTF("N: %d\n", N);
AV *array = newAV();
int i, j;
@@ -983,7 +1003,7 @@
for (j = 0; j < i && !filtered; j++)
if (strcasestr(&vocab[c * max_w], &vocab[chosen[j] * max_w]) ||
strcasestr(&vocab[chosen[j] * max_w], &vocab[c * max_w])) {
- printf("filtering %s %s\n", &vocab[chosen[j] * max_w], &vocab[c * max_w]);
+ DEBUG_PRINTF("filtering %s %s\n", &vocab[chosen[j] * max_w], &vocab[c * max_w]);
filtered = 1;
}
if (filtered)
@@ -1036,16 +1056,16 @@
float total_activation = 0;
if (M2) {
- printf("Waiting for syn threads to join\n");
- fflush(stdout);
+ DEBUG_PRINTF("Waiting for syn threads to join\n");
+ DEBUG_FFLUSH();
for (a = 0; a < syn_threads; a++) pthread_join(pt[a + para_threads], (void *)&syn_nbs[a]);
for (a = 0; a <= syn_threads; a++) {
if (a == window) continue;
total_activation += window_sums[a];
- printf("window pos: %ld, sum: %f\n", a, window_sums[a]);
+ DEBUG_PRINTF("window pos: %ld, sum: %f\n", a, window_sums[a]);
}
- printf("syn threads joint\n");
- fflush(stdout);
+ DEBUG_PRINTF("syn threads joint\n");
+ DEBUG_FFLUSH();
for (b = 0; b < syn_nbs[0]->length; b++) {
memcpy(best + b, &syn_nbs[0]->best[b], sizeof(collocator));
@@ -1079,7 +1099,7 @@
}
sort_by = 0; // ALWAYS AUTO-FOCUS
if (sort_by != 1 && sort_by != 2) { // sort by auto focus mean
- printf("window: %d - syn_threads: %d, %d\n", window, syn_threads, (1 << syn_threads) - 1);
+ DEBUG_PRINTF("window: %d - syn_threads: %d, %d\n", window, syn_threads, (1 << syn_threads) - 1);
int wpos;
int bits_set = 0;
for (i = 0; i < found_index; i++) {
diff --git a/script/derekovecs-server b/script/derekovecs-server
index bc66b01..9f5dbec 100755
--- a/script/derekovecs-server
+++ b/script/derekovecs-server
@@ -222,7 +222,7 @@
my $c = shift;
my $url = $c->req->url;
$url =~ s@/derekovecs/@/@g;
- $c->app->log->info("GET: " . $url);
+ $c->app->log->debug("GET: " . $url);
$c->reply->static($url);
} => 'js';
@@ -230,7 +230,7 @@
my $c = shift;
my $url = $c->req->url;
$url =~ s@/derekovecs/@/@g;
- $c->app->log->info("GET: " . $url);
+ $c->app->log->debug("GET: " . $url);
$c->reply->static($url);
} => 'css';
@@ -412,13 +412,13 @@
my $c = shift;
my $url = $c->req->url;
$url =~ s@/derekovecs@@g;
- $c->app->log->info("GET: " . $url);
+ $c->app->log->debug("GET: " . $url);
$c->reply->static($url);
};
get '/' => sub {
my $c = shift;
- $c->app->log->info("get: ".$c->req->url->to_abs);
+ $c->app->log->debug("get: ".$c->req->url->to_abs);
my $word=$c->param('word');
my $no_nbs=$c->param('n') || ($opt_m? 50 : 100);
my $no_iterations=$c->param('N') || 2000;
@@ -452,9 +452,9 @@
my $key = join("\x1c", $w, $cutoff, $no_nbs, $sort, $dedupe, $searchBaseVocabFirst, $nosp);
$res = $opt_C ? undef : $cache->get($key);
if (defined $res) {
- $c->app->log->info("Getting $w results from cache");
+ $c->app->log->debug("Getting $w results from cache");
} else {
- $c->app->log->info('Looking for neighbours of '.$w);
+ $c->app->log->debug('Looking for neighbours of '.$w);
if($opt_i) {
$res = get_neighbours(encode("iso-8859-1", $w), $no_nbs, $sort, $searchBaseVocabFirst, $cutoff, $dedupe, $nosp);
} else {