Line data Source code
1 : /*
2 : * SPDX-License-Identifier: MPL-2.0
3 : *
4 : * This Source Code Form is subject to the terms of the Mozilla Public
5 : * License, v. 2.0. If a copy of the MPL was not distributed with this
6 : * file, You can obtain one at http://mozilla.org/MPL/2.0/.
7 : *
8 : * Copyright 2024 MonetDB Foundation;
9 : * Copyright August 2008 - 2023 MonetDB B.V.;
10 : * Copyright 1997 - July 2008 CWI.
11 : */
12 :
13 : #include "monetdb_config.h"
14 : #include "gdk.h"
15 : #include "gdk_private.h"
16 : #include "gdk_logger.h"
17 : #include "gdk_logger_internals.h"
18 : #include "mutils.h"
19 : #include <string.h>
20 :
21 : static gdk_return log_add_bat(logger *lg, BAT *b, log_id id, int tid);
22 : static gdk_return log_del_bat(logger *lg, log_bid bid);
23 : /*
24 : * The logger uses a directory to store its log files. One master log
25 : * file stores information about the version of the logger and the
26 : * type mapping it uses. This file is a simple ascii file with the
27 : * following format:
28 : * {6DIGIT-VERSION\n[id,type_name\n]*}
29 : * The transaction log files have a binary format.
30 : */
31 :
32 : #define LOG_START 0
33 : #define LOG_END 1
34 : #define LOG_UPDATE_CONST 2
35 : #define LOG_UPDATE_BULK 3
36 : #define LOG_UPDATE 4
37 : #define LOG_CREATE 5
38 : #define LOG_DESTROY 6
39 : #define LOG_SEQ 7
40 : #define LOG_CLEAR 8 /* DEPRECATED */
41 : #define LOG_BAT_GROUP 9
42 :
43 : #ifdef NATIVE_WIN32
44 : #define getfilepos _ftelli64
45 : #else
46 : #ifdef HAVE_FSEEKO
47 : #define getfilepos ftello
48 : #else
49 : #define getfilepos ftell
50 : #endif
51 : #endif
52 :
53 : #define BATSIZE 0
54 :
55 : #define LOG_DISABLED(lg) ((lg)->debug&128 || (lg)->inmemory || (lg)->flushnow)
56 :
57 : static const char *log_commands[] = {
58 : "LOG_START",
59 : "LOG_END",
60 : "LOG_UPDATE_CONST",
61 : "LOG_UPDATE_BULK",
62 : "LOG_UPDATE",
63 : "LOG_CREATE",
64 : "LOG_DESTROY",
65 : "LOG_SEQ",
66 : "", /* LOG_CLEAR IS DEPRECATED */
67 : "LOG_BAT_GROUP",
68 : };
69 :
70 : typedef struct logaction {
71 : int type; /* type of change */
72 : lng nr;
73 : int tt;
74 : lng id;
75 : lng offset;
76 : log_id cid; /* id of object */
77 : BAT *b; /* temporary bat with changes */
78 : BAT *uid; /* temporary bat with bun positions to update */
79 : } logaction;
80 :
81 : /* during the recover process a number of transactions could be active */
82 : typedef struct trans {
83 : int tid; /* transaction id */
84 : int sz; /* sz of the changes array */
85 : int nr; /* nr of changes */
86 :
87 : logaction *changes;
88 :
89 : struct trans *tr;
90 : } trans;
91 :
92 : typedef struct logformat_t {
93 : bte flag;
94 : int id;
95 : } logformat;
96 :
97 : typedef enum { LOG_OK, LOG_EOF, LOG_ERR } log_return;
98 :
99 : static gdk_return bm_commit(logger *lg, logged_range *pending, uint32_t *updated, BUN maxupdated);
100 : static gdk_return tr_grow(trans *tr);
101 :
102 : #define log_lock(lg) MT_lock_set(&(lg)->lock)
103 : #define log_unlock(lg) MT_lock_unset(&(lg)->lock)
104 :
105 : static inline bte
106 922810 : find_type(logger *lg, int tpe)
107 : {
108 922810 : assert(tpe >= 0 && tpe < MAXATOMS);
109 922810 : return lg->type_id[tpe];
110 : }
111 :
112 : static inline int
113 545466 : find_type_nr(logger *lg, bte tpe)
114 : {
115 545466 : int nr = lg->type_nr[tpe < 0 ? 256 + tpe : tpe];
116 545466 : if (nr == 255)
117 0 : return -1;
118 : return nr;
119 : }
120 :
121 : static BUN
122 421732 : log_find(BAT *b, BAT *d, int val)
123 : {
124 421732 : BUN p;
125 :
126 421732 : assert(b->ttype == TYPE_int);
127 421732 : assert(d->ttype == TYPE_oid);
128 421732 : BATiter bi = bat_iterator(b);
129 421732 : if (BAThash(b) == GDK_SUCCEED) {
130 421732 : MT_rwlock_rdlock(&b->thashlock);
131 702193 : HASHloop_int(bi, b->thash, p, &val) {
132 184587 : oid pos = p;
133 184587 : if (BUNfnd(d, &pos) == BUN_NONE) {
134 184587 : MT_rwlock_rdunlock(&b->thashlock);
135 184587 : bat_iterator_end(&bi);
136 184587 : return p;
137 : }
138 : }
139 237145 : MT_rwlock_rdunlock(&b->thashlock);
140 : } else { /* unlikely: BAThash failed */
141 0 : int *t = (int *) bi.base;
142 :
143 0 : for (p = 0; p < bi.count; p++) {
144 0 : if (t[p] == val) {
145 0 : oid pos = p;
146 0 : if (BUNfnd(d, &pos) == BUN_NONE) {
147 0 : bat_iterator_end(&bi);
148 0 : return p;
149 : }
150 : }
151 : }
152 : }
153 237145 : bat_iterator_end(&bi);
154 237145 : return BUN_NONE;
155 : }
156 :
157 : static log_bid
158 642648 : internal_find_bat(logger *lg, log_id id, int tid)
159 : {
160 642648 : BUN p;
161 :
162 642648 : if (BAThash(lg->catalog_id) == GDK_SUCCEED) {
163 642648 : BATiter cni = bat_iterator(lg->catalog_id);
164 642648 : MT_rwlock_rdlock(&cni.b->thashlock);
165 642648 : if (tid < 0) {
166 384947 : HASHloop_int(cni, cni.b->thash, p, &id) {
167 200864 : oid pos = p;
168 200864 : if (BUNfnd(lg->dcatalog, &pos) == BUN_NONE) {
169 200864 : MT_rwlock_rdunlock(&cni.b->thashlock);
170 200864 : bat_iterator_end(&cni);
171 200864 : return *(log_bid *) Tloc(lg->catalog_bid, p);
172 : }
173 : }
174 : } else {
175 360927 : BUN cp = BUN_NONE;
176 1536001 : HASHloop_int(cni, cni.b->thash, p, &id) {
177 1124724 : lng lid = *(lng *) Tloc(lg->catalog_lid, p);
178 1124724 : if (lid != lng_nil && lid <= tid) {
179 : break;
180 : }
181 : cp = p;
182 : }
183 360927 : if (cp != BUN_NONE) {
184 360678 : MT_rwlock_rdunlock(&cni.b->thashlock);
185 360678 : bat_iterator_end(&cni);
186 360678 : return *(log_bid *) Tloc(lg->catalog_bid, cp);
187 : }
188 : }
189 81106 : MT_rwlock_rdunlock(&cni.b->thashlock);
190 81106 : bat_iterator_end(&cni);
191 81106 : return 0; /* not found */
192 : }
193 : return -1; /* error creating hash */
194 : }
195 :
196 : static inline void
197 14290 : logbat_destroy(BAT *b)
198 : {
199 17861 : BBPreclaim(b);
200 3435 : }
201 :
202 : static BAT *
203 15519 : logbat_new(int tt, BUN size, role_t role)
204 : {
205 15519 : BAT *nb = COLnew(0, tt, size, role);
206 :
207 15519 : if (nb) {
208 15519 : BBP_pid(nb->batCacheid) = 0;
209 15519 : if (role == PERSISTENT) {
210 9759 : BATmode(nb, false);
211 9759 : nb = BATsetaccess(nb, BAT_READ);
212 : }
213 : } else {
214 0 : TRC_CRITICAL(GDK, "creating new BAT[%s]#" BUNFMT " failed\n", ATOMname(tt), size);
215 : }
216 15519 : return nb;
217 : }
218 :
219 : static bool
220 756757 : log_read_format(logger *lg, logformat *data)
221 : {
222 756757 : assert(!lg->inmemory);
223 756757 : if (mnstr_read(lg->input_log, &data->flag, 1, 1) == 1) {
224 744375 : if (mnstr_readInt(lg->input_log, &data->id) == 1)
225 : return true;
226 : /* could only read part, so complain */
227 0 : TRC_CRITICAL(GDK, "read failed\n");
228 : }
229 : return false;
230 : }
231 :
232 : static gdk_return
233 751060 : log_write_format(logger *lg, logformat *data)
234 : {
235 751060 : assert(data->id || data->flag);
236 751060 : assert(!lg->inmemory);
237 751060 : assert(mnstr_errnr(lg->current->output_log) == MNSTR_NO__ERROR);
238 1502120 : if (mnstr_errnr(lg->current->output_log) == MNSTR_NO__ERROR &&
239 1502120 : mnstr_write(lg->current->output_log, &data->flag, 1, 1) == 1 &&
240 751060 : mnstr_writeInt(lg->current->output_log, data->id))
241 : return GDK_SUCCEED;
242 0 : TRC_CRITICAL(GDK, "write failed\n");
243 0 : return GDK_FAIL;
244 : }
245 :
246 : static log_return
247 2759 : log_read_seq(logger *lg, logformat *l)
248 : {
249 2759 : int seq = l->id;
250 2759 : lng val;
251 2759 : BUN p;
252 :
253 2759 : assert(!lg->inmemory);
254 2759 : if (mnstr_readLng(lg->input_log, &val) != 1) {
255 0 : TRC_CRITICAL(GDK, "read failed\n");
256 0 : return LOG_EOF;
257 : }
258 2759 : if (lg->flushing)
259 : return LOG_OK;
260 :
261 60 : if ((p = log_find(lg->seqs_id, lg->dseqs, seq)) != BUN_NONE &&
262 59 : p >= lg->seqs_id->batInserted) {
263 39 : assert(lg->seqs_val->hseqbase == 0);
264 39 : if (BUNreplace(lg->seqs_val, p, &val, true) != GDK_SUCCEED) {
265 0 : TRC_CRITICAL(GDK, "replace of %s_seqs_val failed\n", lg->fn);
266 0 : return LOG_ERR;
267 : }
268 : } else {
269 20 : if (p != BUN_NONE) {
270 20 : oid pos = p;
271 20 : if (BUNappend(lg->dseqs, &pos, true) != GDK_SUCCEED) {
272 0 : TRC_CRITICAL(GDK, "append to %s_dseqs failed\n", lg->fn);
273 0 : return LOG_ERR;
274 : }
275 : }
276 42 : if (BUNappend(lg->seqs_id, &seq, true) != GDK_SUCCEED ||
277 21 : BUNappend(lg->seqs_val, &val, true) != GDK_SUCCEED) {
278 0 : TRC_CRITICAL(GDK, "append to %s_seqs_val/id failed\n", lg->fn);
279 0 : return LOG_ERR;
280 : }
281 : }
282 : return LOG_OK;
283 : }
284 :
285 : #if 0
286 : static gdk_return
287 : log_write_id(logger *lg, int id)
288 : {
289 : assert(!lg->inmemory);
290 : assert(id >= 0);
291 : assert(mnstr_errnr(lg->current->output_log) == MNSTR_NO__ERROR);
292 : if (mnstr_errnr(lg->current->output_log) == MNSTR_NO__ERROR &&
293 : mnstr_writeInt(lg->current->output_log, id))
294 : return GDK_SUCCEED;
295 : TRC_CRITICAL(GDK, "write failed\n");
296 : return GDK_FAIL;
297 : }
298 :
299 : static log_return
300 : log_read_id(logger *lg, log_id *id)
301 : {
302 : assert(!lg->inmemory);
303 : if (mnstr_readInt(lg->input_log, id) != 1) {
304 : TRC_CRITICAL(GDK, "read failed\n");
305 : return LOG_EOF;
306 : }
307 : return LOG_OK;
308 : }
309 : #endif
310 :
311 : static log_return
312 19160 : string_reader(logger *lg, BAT *b, lng nr)
313 : {
314 19160 : size_t sz = 0;
315 19160 : lng SZ = 0;
316 19160 : log_return res = LOG_OK;
317 :
318 38423 : while (nr && res == LOG_OK) {
319 19263 : if (mnstr_readLng(lg->input_log, &SZ) != 1) {
320 0 : TRC_CRITICAL(GDK, "read failed\n");
321 0 : return LOG_EOF;
322 : }
323 19263 : sz = (size_t) SZ;
324 19263 : char *buf = lg->rbuf;
325 19263 : if (lg->rbufsize < sz) {
326 2 : if (!(buf = GDKrealloc(lg->rbuf, sz))) {
327 0 : TRC_CRITICAL(GDK, "couldn't grow string buffer\n");
328 0 : return LOG_ERR;
329 : }
330 2 : lg->rbuf = buf;
331 2 : lg->rbufsize = sz;
332 : }
333 :
334 19263 : if (mnstr_read(lg->input_log, buf, sz, 1) != 1) {
335 0 : TRC_CRITICAL(GDK, "read failed\n");
336 0 : return LOG_EOF;
337 : }
338 : /* handle strings */
339 : char *t = buf;
340 : /* chunked */
341 : #define CHUNK_SIZE 1024
342 : char *strings[CHUNK_SIZE];
343 : int cur = 0;
344 :
345 93133 : for (; nr > 0 && res == LOG_OK && t < (buf + sz); nr--) {
346 73870 : strings[cur++] = t;
347 73870 : if (cur == CHUNK_SIZE &&
348 4 : b &&
349 4 : BUNappendmulti(b, strings, cur, true) != GDK_SUCCEED) {
350 0 : TRC_CRITICAL(GDK, "append to string bat failed\n");
351 0 : res = LOG_ERR;
352 : }
353 73870 : if (cur == CHUNK_SIZE)
354 33 : cur = 0;
355 : /* find next */
356 5578239 : while (*t)
357 5504369 : t++;
358 73870 : t++;
359 : }
360 19263 : if (cur &&
361 294 : b &&
362 294 : BUNappendmulti(b, strings, cur, true) != GDK_SUCCEED) {
363 0 : TRC_CRITICAL(GDK, "append to string bat failed\n");
364 0 : res = LOG_ERR;
365 : }
366 : }
367 : return res;
368 : }
369 :
370 :
371 : struct offset {
372 : lng os; /* offset within source BAT in logfile */
373 : lng nr; /* number of values to be copied */
374 : lng od; /* offset within destination BAT in database */
375 : };
376 :
377 : static log_return
378 388767 : log_read_updates(logger *lg, trans *tr, logformat *l, log_id id, BAT **cands)
379 : {
380 388767 : log_return res = LOG_OK;
381 388767 : lng nr, pnr;
382 388767 : bte type_id = -1;
383 388767 : int tpe;
384 :
385 388767 : assert(!lg->inmemory);
386 388767 : TRC_DEBUG(WAL, "found %d %s", id, l->flag == LOG_UPDATE ? "update" : "update_buld");
387 :
388 777534 : if (mnstr_readLng(lg->input_log, &nr) != 1 ||
389 388767 : mnstr_read(lg->input_log, &type_id, 1, 1) != 1) {
390 0 : TRC_CRITICAL(GDK, "read failed\n");
391 0 : return LOG_EOF;
392 : }
393 :
394 388767 : pnr = nr;
395 388767 : tpe = find_type_nr(lg, type_id);
396 388767 : if (tpe >= 0) {
397 388767 : BAT *uid = NULL;
398 388767 : BAT *r = NULL;
399 388767 : void *(*rt)(ptr, size_t *, stream *, size_t) = BATatoms[tpe].atomRead;
400 388767 : lng offset;
401 :
402 388767 : assert(nr <= (lng) BUN_MAX);
403 388767 : if (!lg->flushing && l->flag == LOG_UPDATE) {
404 0 : uid = COLnew(0, TYPE_oid, (BUN) nr, PERSISTENT);
405 0 : if (uid == NULL) {
406 0 : TRC_CRITICAL(GDK, "creating bat failed\n");
407 28134 : return LOG_ERR;
408 : }
409 : }
410 :
411 388767 : if (l->flag == LOG_UPDATE_CONST) {
412 121276 : if (mnstr_readLng(lg->input_log, &offset) != 1) {
413 0 : TRC_CRITICAL(GDK, "read failed\n");
414 0 : return LOG_EOF;
415 : }
416 121276 : if (cands) {
417 : /* This const range actually represents a segment of candidates corresponding to updated bat entries */
418 :
419 28134 : if (BATcount(*cands) == 0 || lg->flushing) {
420 : /* when flushing, we only need the offset and count of the last segment of inserts. */
421 28134 : assert((*cands)->ttype == TYPE_void);
422 28134 : BATtseqbase(*cands, (oid) offset);
423 28134 : BATsetcount(*cands, (BUN) nr);
424 0 : } else if (!lg->flushing) {
425 0 : assert(BATcount(*cands) > 0);
426 0 : BAT *dense = BATdense(0, (oid) offset, (BUN) nr);
427 0 : BAT *newcands = NULL;
428 0 : if (!dense) {
429 0 : TRC_CRITICAL(GDK, "creating bat failed\n");
430 0 : res = LOG_ERR;
431 0 : } else if ((*cands)->ttype == TYPE_void) {
432 0 : if ((newcands = BATmergecand(*cands, dense))) {
433 0 : BBPreclaim(*cands);
434 0 : *cands = newcands;
435 : } else {
436 0 : TRC_CRITICAL(GDK, "creating bat failed\n");
437 0 : res = LOG_ERR;
438 : }
439 : } else {
440 0 : assert((*cands)->ttype == TYPE_oid);
441 0 : assert(BATcount(*cands) > 0);
442 0 : if (BATappend(*cands, dense, NULL, true) != GDK_SUCCEED) {
443 0 : TRC_CRITICAL(GDK, "appending to bat failed\n");
444 0 : res = LOG_ERR;
445 : }
446 : }
447 0 : BBPreclaim(dense);
448 : }
449 :
450 : /* We have to read the value to update the read cursor */
451 28134 : size_t tlen = lg->rbufsize;
452 28134 : void *t = rt(lg->rbuf, &tlen, lg->input_log, 1);
453 28134 : if (t == NULL) {
454 0 : TRC_CRITICAL(GDK, "read failed\n");
455 0 : res = LOG_EOF;
456 : }
457 28134 : return res;
458 : }
459 : }
460 :
461 360633 : if (!lg->flushing) {
462 1261 : r = COLnew(0, tpe, (BUN) nr, PERSISTENT);
463 1261 : if (r == NULL) {
464 0 : if (uid)
465 0 : BBPreclaim(uid);
466 0 : return LOG_ERR;
467 : }
468 : }
469 :
470 360633 : if (l->flag == LOG_UPDATE_CONST) {
471 93142 : size_t tlen = lg->rbufsize;
472 93142 : void *t = rt(lg->rbuf, &tlen, lg->input_log, 1);
473 93142 : if (t == NULL) {
474 0 : TRC_CRITICAL(GDK, "read failed\n");
475 0 : res = LOG_EOF;
476 : } else {
477 93142 : lg->rbuf = t;
478 93142 : lg->rbufsize = tlen;
479 93142 : if (r) {
480 8117 : for (BUN p = 0; p < (BUN) nr; p++) {
481 7873 : if (BUNappend(r, t, true) != GDK_SUCCEED) {
482 0 : TRC_CRITICAL(GDK, "append to bat failed\n");
483 0 : res = LOG_ERR;
484 : }
485 : }
486 : }
487 : }
488 267491 : } else if (l->flag == LOG_UPDATE_BULK) {
489 267473 : if (mnstr_readLng(lg->input_log, &offset) != 1) {
490 0 : if (r)
491 0 : BBPreclaim(r);
492 0 : TRC_CRITICAL(GDK, "read failed\n");
493 0 : return LOG_EOF;
494 : }
495 267473 : if (tpe == TYPE_msk) {
496 0 : if (r) {
497 0 : if (mnstr_readIntArray(lg->input_log, Tloc(r, 0), (size_t) ((nr + 31) / 32)))
498 0 : BATsetcount(r, (BUN) nr);
499 : else {
500 0 : TRC_CRITICAL(GDK, "read failed\n");
501 0 : res = LOG_EOF;
502 : }
503 : } else {
504 0 : size_t tlen = lg->rbufsize / sizeof(int);
505 0 : size_t cnt = 0, snr = (size_t) nr;
506 0 : snr = (snr + 31) / 32;
507 0 : assert(tlen);
508 0 : for (; res == LOG_OK && snr > 0; snr -= cnt) {
509 0 : cnt = snr > tlen ? tlen : snr;
510 0 : if (!mnstr_readIntArray(lg->input_log, lg->rbuf, cnt)) {
511 0 : TRC_CRITICAL(GDK, "read failed\n");
512 0 : res = LOG_EOF;
513 : }
514 : }
515 : }
516 : } else {
517 267473 : if (!ATOMvarsized(tpe)) {
518 247737 : size_t cnt = 0, snr = (size_t) nr;
519 247737 : size_t tlen = lg->rbufsize / ATOMsize(tpe), ntlen = lg->rbufsize;
520 247737 : assert(tlen);
521 : /* read in chunks of max
522 : * BUFSIZE/width rows */
523 508143 : for (; res == LOG_OK && snr > 0; snr -= cnt) {
524 260406 : cnt = snr > tlen ? tlen : snr;
525 260406 : void *t = rt(lg->rbuf, &ntlen, lg->input_log, cnt);
526 :
527 260406 : if (t == NULL) {
528 : res = LOG_EOF;
529 : break;
530 : }
531 260406 : assert(t == lg->rbuf);
532 260406 : if (r && BUNappendmulti(r, t, cnt, true) != GDK_SUCCEED) {
533 0 : TRC_CRITICAL(GDK, "append to bat failed\n");
534 0 : res = LOG_ERR;
535 : }
536 : }
537 19736 : } else if (tpe == TYPE_str) {
538 : /* efficient string */
539 19154 : res = string_reader(lg, r, nr);
540 : } else {
541 1206 : for (; res == LOG_OK && nr > 0; nr--) {
542 624 : size_t tlen = lg->rbufsize;
543 624 : void *t = rt(lg->rbuf, &tlen, lg->input_log, 1);
544 :
545 624 : if (t == NULL) {
546 : /* see if failure was due to
547 : * malloc or something less
548 : * serious (in the current
549 : * context) */
550 0 : if (strstr(GDKerrbuf, "alloc") == NULL)
551 : res = LOG_EOF;
552 : else
553 0 : res = LOG_ERR;
554 0 : TRC_CRITICAL(GDK, "read failed\n");
555 : } else {
556 624 : lg->rbuf = t;
557 624 : lg->rbufsize = tlen;
558 624 : if (r && BUNappend(r, t, true) != GDK_SUCCEED) {
559 0 : TRC_CRITICAL(GDK, "append to bat failed\n");
560 0 : res = LOG_ERR;
561 : }
562 : }
563 : }
564 : }
565 : }
566 : } else {
567 18 : void *(*rh)(ptr, size_t *, stream *, size_t) = BATatoms[TYPE_oid].atomRead;
568 18 : void *hv = ATOMnil(TYPE_oid);
569 18 : offset = 0;
570 :
571 18 : if (hv == NULL) {
572 0 : TRC_CRITICAL(GDK, "read failed\n");
573 0 : res = LOG_EOF;
574 : }
575 1071 : for (; res == LOG_OK && nr > 0; nr--) {
576 1053 : size_t hlen = sizeof(oid);
577 1053 : void *h = rh(hv, &hlen, lg->input_log, 1);
578 1053 : assert(hlen == sizeof(oid));
579 1053 : assert(h == hv);
580 1053 : if ((uid && BUNappend(uid, h, true) != GDK_SUCCEED)) {
581 0 : TRC_CRITICAL(GDK, "append to bat failed\n");
582 0 : res = LOG_ERR;
583 : }
584 : }
585 18 : nr = pnr;
586 18 : if (tpe == TYPE_msk) {
587 0 : if (r) {
588 0 : if (mnstr_readIntArray(lg->input_log, Tloc(r, 0), (size_t) ((nr + 31) / 32)))
589 0 : BATsetcount(r, (BUN) nr);
590 : else {
591 0 : TRC_CRITICAL(GDK, "read failed\n");
592 0 : res = LOG_EOF;
593 : }
594 : } else {
595 0 : for (lng i = 0; i < nr; i += 32) {
596 0 : int v;
597 0 : switch (mnstr_readInt(lg->input_log, &v)) {
598 0 : case 1:
599 0 : continue;
600 : case 0:
601 : res = LOG_EOF;
602 : break;
603 : default:
604 : res = LOG_ERR;
605 : break;
606 : }
607 0 : TRC_CRITICAL(GDK, "read failed\n");
608 0 : break;
609 : }
610 : }
611 18 : } else if (tpe == TYPE_str) {
612 : /* efficient string */
613 6 : res = string_reader(lg, r, nr);
614 : } else {
615 58 : for (; res == LOG_OK && nr > 0; nr--) {
616 46 : size_t tlen = lg->rbufsize;
617 46 : void *t = rt(lg->rbuf, &tlen, lg->input_log, 1);
618 :
619 46 : if (t == NULL) {
620 0 : if (strstr(GDKerrbuf, "malloc") == NULL)
621 : res = LOG_EOF;
622 : else
623 0 : res = LOG_ERR;
624 0 : TRC_CRITICAL(GDK, "read failed\n");
625 : } else {
626 46 : lg->rbuf = t;
627 46 : lg->rbufsize = tlen;
628 46 : if ((r && BUNappend(r, t, true) != GDK_SUCCEED)) {
629 0 : TRC_CRITICAL(GDK, "append to bat failed\n");
630 0 : res = LOG_ERR;
631 : }
632 : }
633 : }
634 : }
635 18 : GDKfree(hv);
636 : }
637 :
638 360633 : if (res == LOG_OK) {
639 360633 : if (tr_grow(tr) == GDK_SUCCEED) {
640 360633 : tr->changes[tr->nr].type = l->flag;
641 360633 : if (l->flag == LOG_UPDATE_BULK && offset == -1) {
642 138769 : assert(cands); /* bat r is part of a group of bats logged together. */
643 138769 : struct canditer ci;
644 138769 : canditer_init(&ci, NULL, *cands);
645 138769 : const oid first = canditer_peek(&ci);
646 138769 : const oid last = canditer_last(&ci);
647 138769 : offset = (lng) first;
648 138769 : pnr = (lng) (last - first) + 1;
649 138769 : if (!lg->flushing) {
650 913 : assert(uid == NULL);
651 913 : uid = *cands;
652 913 : BBPfix((*cands)->batCacheid);
653 913 : tr->changes[tr->nr].type = LOG_UPDATE;
654 : }
655 : }
656 360633 : if (l->flag == LOG_UPDATE_CONST) {
657 93142 : assert(!cands); /* TODO: This might change in the future. */
658 93142 : tr->changes[tr->nr].type = LOG_UPDATE_BULK;
659 : }
660 360633 : tr->changes[tr->nr].nr = pnr;
661 360633 : tr->changes[tr->nr].tt = tpe;
662 360633 : tr->changes[tr->nr].cid = id;
663 360633 : tr->changes[tr->nr].offset = offset;
664 360633 : tr->changes[tr->nr].b = r;
665 360633 : tr->changes[tr->nr].uid = uid;
666 360633 : tr->nr++;
667 : } else {
668 0 : TRC_CRITICAL(GDK, "memory allocation failed\n");
669 0 : res = LOG_ERR;
670 : }
671 : }
672 360633 : if (res != LOG_OK) {
673 0 : if (r)
674 0 : BBPreclaim(r);
675 0 : if (cands && uid)
676 0 : BBPunfix((*cands)->batCacheid);
677 0 : else if (uid)
678 0 : BBPreclaim(uid);
679 : }
680 : } else {
681 : /* bat missing ERROR or ignore ? currently error. */
682 0 : TRC_CRITICAL(GDK, "unknown type\n");
683 0 : res = LOG_ERR;
684 : }
685 : return res;
686 : }
687 :
688 :
689 : static gdk_return
690 567985 : la_bat_update_count(logger *lg, log_id id, lng cnt, int tid)
691 : {
692 567985 : BATiter cni = bat_iterator_nolock(lg->catalog_id);
693 :
694 567985 : if (BAThash(lg->catalog_id) == GDK_SUCCEED) {
695 567985 : MT_rwlock_rdlock(&cni.b->thashlock);
696 567985 : BUN p, cp = BUN_NONE;
697 :
698 2115380 : HASHloop_int(cni, cni.b->thash, p, &id) {
699 1334561 : lng lid = *(lng *) Tloc(lg->catalog_lid, p);
700 :
701 1334561 : if (lid != lng_nil && lid <= tid)
702 : break;
703 : cp = p;
704 : }
705 567985 : if (cp != BUN_NONE) {
706 567783 : lng ocnt = *(lng *) Tloc(lg->catalog_cnt, cp);
707 567783 : assert(lg->catalog_cnt->hseqbase == 0);
708 567783 : if (ocnt < cnt && BUNreplace(lg->catalog_cnt, cp, &cnt, false) != GDK_SUCCEED) {
709 0 : MT_rwlock_rdunlock(&cni.b->thashlock);
710 0 : return GDK_FAIL;
711 : }
712 : }
713 567985 : MT_rwlock_rdunlock(&cni.b->thashlock);
714 567985 : return GDK_SUCCEED;
715 : }
716 : return GDK_FAIL;
717 : }
718 :
719 : static gdk_return
720 360633 : la_bat_updates(logger *lg, logaction *la, int tid)
721 : {
722 360633 : log_bid bid = internal_find_bat(lg, la->cid, tid);
723 360633 : BAT *b = NULL;
724 :
725 360633 : if (bid < 0)
726 : return GDK_FAIL;
727 360633 : if (!bid) {
728 : /* object already gone, nothing needed */
729 : return GDK_SUCCEED;
730 : }
731 :
732 360630 : if (!lg->flushing) {
733 1261 : b = BATdescriptor(bid);
734 1261 : if (b == NULL)
735 : return GDK_FAIL;
736 : }
737 360630 : BUN cnt = 0;
738 360630 : if (la->type == LOG_UPDATE_BULK) {
739 359699 : if (!lg->flushing) {
740 348 : cnt = BATcount(b);
741 348 : int is_msk = (b->ttype == TYPE_msk);
742 : /* handle offset 0 ie clear */
743 348 : if ( /* DISABLES CODE */ (0) && la->offset == 0 && cnt)
744 : BATclear(b, true);
745 : /* handle offset */
746 348 : if (cnt <= (BUN) la->offset) {
747 223 : msk t = 1;
748 223 : if (cnt < (BUN) la->offset) { /* insert nils */
749 0 : const void *tv = (is_msk) ? &t : ATOMnilptr(b->ttype);
750 0 : lng i, d = la->offset - BATcount(b);
751 0 : for (i = 0; i < d; i++) {
752 0 : if (BUNappend(b, tv, true) != GDK_SUCCEED) {
753 0 : logbat_destroy(b);
754 0 : return GDK_FAIL;
755 : }
756 : }
757 : }
758 223 : if (BATcount(b) == (BUN) la->offset && BATappend(b, la->b, NULL, true) != GDK_SUCCEED) {
759 0 : logbat_destroy(b);
760 0 : return GDK_FAIL;
761 : }
762 : } else {
763 125 : BATiter vi = bat_iterator(la->b);
764 125 : BUN p, q;
765 :
766 2167 : for (p = 0, q = (BUN) la->offset; p < (BUN) la->nr; p++, q++) {
767 2042 : const void *t = BUNtail(vi, p);
768 :
769 2042 : if (q < cnt) {
770 2041 : if (b->tnosorted == q)
771 7 : b->tnosorted = 0;
772 2041 : if (b->tnorevsorted == q)
773 7 : b->tnorevsorted = 0;
774 2041 : if (b->tnokey[0] == q ||
775 2034 : b->tnokey[1] == q) {
776 7 : b->tnokey[0] = 0;
777 7 : b->tnokey[1] = 0;
778 : }
779 2041 : b->tkey = false;
780 2041 : b->tsorted = false;
781 2041 : b->tkey = false;
782 2041 : if (BUNreplace(b, q, t, true) != GDK_SUCCEED) {
783 0 : logbat_destroy(b);
784 0 : bat_iterator_end(&vi);
785 0 : return GDK_FAIL;
786 : }
787 : } else {
788 1 : if (BUNappend(b, t, true) != GDK_SUCCEED) {
789 0 : logbat_destroy(b);
790 0 : bat_iterator_end(&vi);
791 0 : return GDK_FAIL;
792 : }
793 : }
794 : }
795 125 : bat_iterator_end(&vi);
796 : }
797 : }
798 931 : } else if (la->type == LOG_UPDATE) {
799 931 : if (!lg->flushing && BATupdate(b, la->uid, la->b, true) != GDK_SUCCEED) {
800 : return GDK_FAIL;
801 : }
802 : }
803 360630 : cnt = (BUN) (la->offset + la->nr);
804 360630 : if (la_bat_update_count(lg, la->cid, cnt, tid) != GDK_SUCCEED) {
805 0 : if (b)
806 0 : logbat_destroy(b);
807 0 : return GDK_FAIL;
808 : }
809 360630 : if (b)
810 1261 : logbat_destroy(b);
811 : return GDK_SUCCEED;
812 : }
813 :
814 : static log_return
815 8740 : log_read_destroy(logger *lg, trans *tr, log_id id)
816 : {
817 8740 : (void) lg;
818 8740 : assert(!lg->inmemory);
819 8740 : if (tr_grow(tr) == GDK_SUCCEED) {
820 8740 : tr->changes[tr->nr].type = LOG_DESTROY;
821 8740 : tr->changes[tr->nr].cid = id;
822 8740 : tr->nr++;
823 8740 : return LOG_OK;
824 : }
825 0 : TRC_CRITICAL(GDK, "memory allocation failed\n");
826 0 : return LOG_ERR;
827 : }
828 :
829 : static gdk_return
830 40 : la_bat_destroy(logger *lg, logaction *la, int tid)
831 : {
832 40 : log_bid bid = internal_find_bat(lg, la->cid, tid);
833 :
834 40 : if (bid < 0)
835 : return GDK_FAIL;
836 40 : if (!bid) {
837 : #ifndef NDEBUG
838 0 : GDKwarning("failed to find bid for object %d\n", la->cid);
839 : #endif
840 0 : return GDK_SUCCEED;
841 : }
842 40 : if (bid && log_del_bat(lg, bid) != GDK_SUCCEED)
843 : return GDK_FAIL;
844 : return GDK_SUCCEED;
845 : }
846 :
847 : static log_return
848 156699 : log_read_create(logger *lg, trans *tr, log_id id)
849 : {
850 156699 : bte tt;
851 156699 : int tpe;
852 :
853 156699 : assert(!lg->inmemory);
854 156699 : TRC_DEBUG(WAL, "create %d", id);
855 :
856 156699 : if (mnstr_read(lg->input_log, &tt, 1, 1) != 1) {
857 0 : TRC_CRITICAL(GDK, "read failed\n");
858 0 : return LOG_EOF;
859 : }
860 :
861 156699 : tpe = find_type_nr(lg, tt);
862 : /* read create */
863 156699 : if (tr_grow(tr) == GDK_SUCCEED) {
864 156699 : tr->changes[tr->nr].type = LOG_CREATE;
865 156699 : tr->changes[tr->nr].tt = tpe;
866 156699 : tr->changes[tr->nr].cid = id;
867 156699 : tr->nr++;
868 156699 : return LOG_OK;
869 : }
870 0 : TRC_CRITICAL(GDK, "memory allocation failed\n");
871 0 : return LOG_ERR;
872 : }
873 :
874 : static gdk_return
875 254 : la_bat_create(logger *lg, logaction *la, int tid)
876 : {
877 254 : BAT *b;
878 :
879 : /* formerly head column type, should be void */
880 254 : if ((b = COLnew(0, la->tt, BATSIZE, PERSISTENT)) == NULL)
881 : return GDK_FAIL;
882 :
883 254 : if (la->tt < 0)
884 0 : BATtseqbase(b, 0);
885 :
886 508 : if ((b = BATsetaccess(b, BAT_READ)) == NULL ||
887 254 : log_add_bat(lg, b, la->cid, tid) != GDK_SUCCEED) {
888 0 : logbat_destroy(b);
889 0 : return GDK_FAIL;
890 : }
891 254 : logbat_destroy(b);
892 254 : return GDK_SUCCEED;
893 : }
894 :
895 : static gdk_return
896 241 : log_write_new_types(logger *lg, FILE *fp)
897 : {
898 241 : bte id = 0;
899 :
900 : /* write types and insert into bats */
901 241 : memset(lg->type_id, -1, sizeof(lg->type_id));
902 241 : memset(lg->type_nr, 255, sizeof(lg->type_nr));
903 : /* first the fixed sized types */
904 7468 : for (int i = 0; i < GDKatomcnt; i++) {
905 7227 : if (ATOMvarsized(i))
906 1926 : continue;
907 5301 : lg->type_id[i] = id;
908 5301 : lg->type_nr[id] = i;
909 5301 : if (fprintf(fp, "%d,%s\n", id, BATatoms[i].name) < 0)
910 : return GDK_FAIL;
911 5301 : id++;
912 : }
913 : /* second the var sized types */
914 : id = -127; /* start after nil */
915 7468 : for (int i = 0; i < GDKatomcnt; i++) {
916 7227 : if (!ATOMvarsized(i))
917 5301 : continue;
918 1926 : lg->type_id[i] = id;
919 1926 : lg->type_nr[256 + id] = i;
920 1926 : if (fprintf(fp, "%d,%s\n", id, BATatoms[i].name) < 0)
921 : return GDK_FAIL;
922 1926 : id++;
923 : }
924 : return GDK_SUCCEED;
925 : }
926 :
927 : #define TR_SIZE 1024
928 :
929 : static trans *
930 56330 : tr_create(trans *tr, int tid)
931 : {
932 56330 : trans *ntr = GDKmalloc(sizeof(trans));
933 :
934 56330 : if (ntr == NULL)
935 : return NULL;
936 56330 : ntr->tid = tid;
937 56330 : ntr->sz = TR_SIZE;
938 56330 : ntr->nr = 0;
939 56330 : ntr->changes = GDKmalloc(sizeof(logaction) * TR_SIZE);
940 56330 : if (ntr->changes == NULL) {
941 0 : GDKfree(ntr);
942 0 : return NULL;
943 : }
944 56330 : ntr->tr = tr;
945 56330 : return ntr;
946 : }
947 :
948 : static gdk_return
949 526072 : la_apply(logger *lg, logaction *c, int tid)
950 : {
951 526072 : gdk_return ret = GDK_SUCCEED;
952 :
953 526072 : switch (c->type) {
954 360633 : case LOG_UPDATE_BULK:
955 : case LOG_UPDATE:
956 360633 : ret = la_bat_updates(lg, c, tid);
957 360633 : break;
958 156699 : case LOG_CREATE:
959 156699 : if (!lg->flushing)
960 254 : ret = la_bat_create(lg, c, tid);
961 : break;
962 8740 : case LOG_DESTROY:
963 8740 : if (!lg->flushing)
964 40 : ret = la_bat_destroy(lg, c, tid);
965 : break;
966 : default:
967 0 : MT_UNREACHABLE();
968 : }
969 526072 : return ret;
970 : }
971 :
972 : static void
973 526072 : la_destroy(logaction *c)
974 : {
975 526072 : if ((c->type == LOG_UPDATE || c->type == LOG_UPDATE_BULK) && c->b)
976 1261 : logbat_destroy(c->b);
977 526072 : if (c->type == LOG_UPDATE && c->uid)
978 913 : logbat_destroy(c->uid);
979 526072 : }
980 :
981 : static gdk_return
982 526072 : tr_grow(trans *tr)
983 : {
984 526072 : if (tr->nr == tr->sz) {
985 7 : logaction *changes;
986 7 : tr->sz <<= 1;
987 7 : changes = GDKrealloc(tr->changes, tr->sz * sizeof(logaction));
988 7 : if (changes == NULL)
989 : return GDK_FAIL;
990 7 : tr->changes = changes;
991 : }
992 : /* cleanup the next */
993 526072 : tr->changes[tr->nr].b = NULL;
994 526072 : return GDK_SUCCEED;
995 : }
996 :
997 : static trans *
998 56330 : tr_destroy(trans *tr)
999 : {
1000 56330 : trans *r = tr->tr;
1001 :
1002 56330 : GDKfree(tr->changes);
1003 56330 : GDKfree(tr);
1004 56330 : return r;
1005 : }
1006 :
1007 : static trans *
1008 0 : tr_abort_(logger *lg, trans *tr, int s)
1009 : {
1010 0 : int i;
1011 :
1012 0 : (void) lg;
1013 :
1014 0 : TRC_DEBUG(WAL, "abort");
1015 :
1016 0 : for (i = s; i < tr->nr; i++)
1017 0 : la_destroy(&tr->changes[i]);
1018 0 : return tr_destroy(tr);
1019 : }
1020 :
1021 : static trans *
1022 0 : tr_abort(logger *lg, trans *tr)
1023 : {
1024 0 : return tr_abort_(lg, tr, 0);
1025 : }
1026 :
1027 : static trans *
1028 56330 : tr_commit(logger *lg, trans *tr)
1029 : {
1030 56330 : int i;
1031 :
1032 56330 : TRC_DEBUG(WAL, "commit");
1033 :
1034 582402 : for (i = 0; i < tr->nr; i++) {
1035 526072 : if (la_apply(lg, &tr->changes[i], tr->tid) != GDK_SUCCEED) {
1036 0 : TRC_CRITICAL(GDK, "aborting transaction\n");
1037 0 : do {
1038 0 : tr = tr_abort_(lg, tr, i);
1039 0 : } while (tr != NULL);
1040 : return (trans *) -1;
1041 : }
1042 526072 : la_destroy(&tr->changes[i]);
1043 : }
1044 56330 : lg->saved_tid = tr->tid;
1045 56330 : return tr_destroy(tr);
1046 : }
1047 :
1048 : static gdk_return
1049 89 : log_read_types_file(logger *lg, FILE *fp, int version)
1050 : {
1051 89 : int id = 0;
1052 89 : char atom_name[IDLENGTH];
1053 89 : bool seen_geom = false;
1054 :
1055 : /* scanf should use IDLENGTH somehow */
1056 2729 : while (fscanf(fp, "%d,%63s\n", &id, atom_name) == 2) {
1057 2640 : if (version < 52303 && strcmp(atom_name, "BAT") == 0)
1058 8 : continue;
1059 2632 : int i = ATOMindex(atom_name);
1060 :
1061 2632 : if (id < -127 || id > 127 || i < 0) {
1062 0 : GDKerror("unknown type in log file '%s'\n", atom_name);
1063 0 : return GDK_FAIL;
1064 : }
1065 2632 : seen_geom |= strcmp(atom_name, "mbr") == 0 || strcmp(atom_name, "wkb") == 0;
1066 2632 : lg->type_id[i] = (int8_t) id;
1067 2632 : lg->type_nr[id < 0 ? 256 + id : id] = i;
1068 : }
1069 : #ifdef HAVE_GEOM
1070 89 : if (!seen_geom && ATOMindex("mbr") > 0) {
1071 0 : GDKerror("incompatible database: server supports GEOM, but database does not\n");
1072 0 : return GDK_FAIL;
1073 : }
1074 : #endif
1075 : (void) seen_geom;
1076 : return GDK_SUCCEED;
1077 : }
1078 :
1079 :
1080 : gdk_return
1081 241 : log_create_types_file(logger *lg, const char *filename)
1082 : {
1083 241 : FILE *fp;
1084 :
1085 241 : if ((fp = MT_fopen(filename, "w")) == NULL) {
1086 0 : GDKerror("cannot create log file %s\n", filename);
1087 0 : return GDK_FAIL;
1088 : }
1089 241 : if (fprintf(fp, "%06d\n\n", lg->version) < 0) {
1090 0 : fclose(fp);
1091 0 : GDKerror("writing log file %s failed", filename);
1092 0 : if (MT_remove(filename) < 0)
1093 0 : GDKsyserror("remove %s failed\n", filename);
1094 0 : return GDK_FAIL;
1095 : }
1096 :
1097 241 : if (log_write_new_types(lg, fp) != GDK_SUCCEED) {
1098 0 : fclose(fp);
1099 0 : GDKerror("writing log file %s failed", filename);
1100 0 : if (MT_remove(filename) < 0)
1101 0 : GDKsyserror("remove %s failed\n", filename);
1102 0 : return GDK_FAIL;
1103 : }
1104 241 : if (fflush(fp) < 0 || (!(ATOMIC_GET(&GDKdebug) & NOSYNCMASK)
1105 : #if defined(_MSC_VER)
1106 : && _commit(_fileno(fp)) < 0
1107 : #elif defined(HAVE_FDATASYNC)
1108 0 : && fdatasync(fileno(fp)) < 0
1109 : #elif defined(HAVE_FSYNC)
1110 : && fsync(fileno(fp)) < 0
1111 : #endif
1112 : )) {
1113 0 : GDKsyserror("flushing log file %s failed", filename);
1114 0 : fclose(fp);
1115 0 : if (MT_remove(filename) < 0)
1116 0 : GDKsyserror("remove %s failed\n", filename);
1117 0 : return GDK_FAIL;
1118 : }
1119 241 : if (fclose(fp) < 0) {
1120 0 : GDKsyserror("closing log file %s failed", filename);
1121 0 : if (MT_remove(filename) < 0)
1122 0 : GDKsyserror("remove %s failed\n", filename);
1123 0 : return GDK_FAIL;
1124 : }
1125 : return GDK_SUCCEED;
1126 : }
1127 :
1128 : #define rotation_lock(lg) MT_lock_set(&(lg)->rotation_lock)
1129 : #define rotation_unlock(lg) MT_lock_unset(&(lg)->rotation_lock)
1130 : #define rotation_trylock(lg, ms) MT_lock_trytime(&(lg)->rotation_lock, ms)
1131 :
1132 : static gdk_return
1133 12649 : log_open_output(logger *lg)
1134 : {
1135 12649 : logged_range *new_range = (logged_range *) GDKmalloc(sizeof(logged_range));
1136 :
1137 12649 : if (!new_range) {
1138 0 : TRC_CRITICAL(GDK, "allocation failure\n");
1139 0 : return GDK_FAIL;
1140 : }
1141 25297 : if (!LOG_DISABLED(lg)) {
1142 12648 : char id[32];
1143 12648 : char *filename;
1144 :
1145 12648 : if (snprintf(id, sizeof(id), LLFMT, lg->id) >= (int) sizeof(id)) {
1146 0 : TRC_CRITICAL(GDK, "filename is too large\n");
1147 0 : GDKfree(new_range);
1148 0 : return GDK_FAIL;
1149 : }
1150 12648 : if ((filename = GDKfilepath(BBPselectfarm(PERSISTENT, 0, offheap), lg->dir, LOGFILE, id)) == NULL) {
1151 0 : TRC_CRITICAL(GDK, "allocation failure\n");
1152 0 : GDKfree(new_range);
1153 0 : return GDK_FAIL;
1154 : }
1155 :
1156 12648 : TRC_INFO(WAL, "opening %s.%s", LOGFILE, id);
1157 12648 : new_range->output_log = open_wstream(filename);
1158 12648 : if (new_range->output_log) {
1159 12648 : short byteorder = 1234;
1160 12648 : mnstr_write(new_range->output_log, &byteorder, sizeof(byteorder), 1);
1161 : }
1162 :
1163 12648 : if (new_range->output_log == NULL || mnstr_errnr(new_range->output_log) != MNSTR_NO__ERROR) {
1164 0 : TRC_CRITICAL(GDK, "creating %s failed: %s\n", filename, mnstr_peek_error(NULL));
1165 0 : close_stream(new_range->output_log);
1166 0 : GDKfree(new_range);
1167 0 : GDKfree(filename);
1168 0 : return GDK_FAIL;
1169 : }
1170 12648 : GDKfree(filename);
1171 : } else {
1172 1 : new_range->output_log = NULL;
1173 : }
1174 12649 : ATOMIC_INIT(&new_range->refcount, 1);
1175 12649 : ATOMIC_INIT(&new_range->last_ts, 0);
1176 12649 : ATOMIC_INIT(&new_range->flushed_ts, 0);
1177 12649 : ATOMIC_INIT(&new_range->drops, 0);
1178 12649 : new_range->id = lg->id;
1179 12649 : new_range->next = NULL;
1180 12649 : logged_range *current = lg->current;
1181 12649 : assert(current && current->next == NULL);
1182 12649 : new_range->cnt = current->cnt;
1183 12649 : current->next = new_range;
1184 12649 : lg->file_age = GDKusec();
1185 12649 : return GDK_SUCCEED;
1186 : }
1187 :
1188 : static inline void
1189 12774 : log_close_input(logger *lg)
1190 : {
1191 12774 : if (!lg->inmemory && lg->input_log) {
1192 12387 : TRC_INFO(WAL, "closing input log %s", mnstr_name(lg->input_log));
1193 12387 : close_stream(lg->input_log);
1194 : }
1195 12774 : lg->input_log = NULL;
1196 12774 : }
1197 :
1198 : static inline void
1199 298 : log_close_output(logger *lg)
1200 : {
1201 298 : if (!LOG_DISABLED(lg) && lg->current->output_log) {
1202 297 : TRC_INFO(WAL, "closing output log %s", mnstr_name(lg->current->output_log));
1203 297 : close_stream(lg->current->output_log);
1204 : }
1205 298 : lg->current->output_log = NULL;
1206 298 : }
1207 :
1208 : static gdk_return
1209 12476 : log_open_input(logger *lg, const char *filename, bool *filemissing)
1210 : {
1211 12476 : TRC_INFO(WAL, "opening input log %s", filename);
1212 12476 : lg->input_log = open_rstream(filename);
1213 :
1214 : /* if the file doesn't exist, there is nothing to be read back */
1215 12476 : if (lg->input_log == NULL || mnstr_errnr(lg->input_log) != MNSTR_NO__ERROR) {
1216 89 : log_close_input(lg);
1217 89 : *filemissing = true;
1218 89 : return GDK_SUCCEED;
1219 : }
1220 12387 : short byteorder;
1221 12387 : switch (mnstr_read(lg->input_log, &byteorder, sizeof(byteorder), 1)) {
1222 0 : case -1:
1223 0 : log_close_input(lg);
1224 0 : TRC_CRITICAL(GDK, "read failed\n");
1225 0 : return GDK_FAIL;
1226 5 : case 0:
1227 : /* empty file is ok */
1228 5 : log_close_input(lg);
1229 5 : return GDK_SUCCEED;
1230 12382 : case 1:
1231 : /* if not empty, must start with correct byte order mark */
1232 12382 : if (byteorder != 1234) {
1233 0 : TRC_CRITICAL(GDK, "incorrect byte order word in file %s\n", filename);
1234 0 : log_close_input(lg);
1235 0 : return GDK_FAIL;
1236 : }
1237 : break;
1238 : }
1239 : return GDK_SUCCEED;
1240 : }
1241 :
1242 : static log_return
1243 12382 : log_read_transaction(logger *lg, uint32_t *updated, BUN maxupdated)
1244 : {
1245 12382 : logformat l;
1246 12382 : trans *tr = NULL;
1247 12382 : log_return err = LOG_OK;
1248 12382 : bool ok = true;
1249 12382 : ATOMIC_BASE_TYPE dbg = ATOMIC_GET(&GDKdebug);
1250 :
1251 12382 : (void) maxupdated; /* only used inside assert() */
1252 :
1253 12382 : if (!lg->flushing)
1254 141 : ATOMIC_AND(&GDKdebug, ~CHECKMASK);
1255 :
1256 12382 : BAT *cands = NULL; /* used in case of LOG_BAT_GROUP */
1257 :
1258 756757 : while (err == LOG_OK && (ok = log_read_format(lg, &l))) {
1259 744375 : if (l.flag == 0 && l.id == 0) {
1260 12382 : err = LOG_EOF;
1261 : break;
1262 : }
1263 :
1264 744375 : TRC_DEBUG_IF(WAL) {
1265 0 : if (l.flag > 0 && l.flag != LOG_CLEAR &&
1266 : l.flag < (bte) (sizeof(log_commands) / sizeof(log_commands[0])))
1267 0 : TRC_DEBUG_ENDIF(WAL, "%s %d", log_commands[(int) l.flag], l.id);
1268 : else
1269 0 : TRC_DEBUG_ENDIF(WAL, "%d %d", l.flag, l.id);
1270 : }
1271 744375 : switch (l.flag) {
1272 554206 : case LOG_UPDATE_CONST:
1273 : case LOG_UPDATE_BULK:
1274 : case LOG_UPDATE:
1275 : case LOG_CREATE:
1276 : case LOG_DESTROY:
1277 554206 : if (tr != NULL && updated && BAThash(lg->catalog_id) == GDK_SUCCEED) {
1278 552494 : BATiter cni = bat_iterator(lg->catalog_id);
1279 552494 : BUN p;
1280 552494 : BUN posnew = BUN_NONE;
1281 552494 : BUN posold = BUN_NONE;
1282 552494 : MT_rwlock_rdlock(&cni.b->thashlock);
1283 4182625 : HASHloop_int(cni, cni.b->thash, p, &l.id) {
1284 3266240 : lng lid = *(lng *) Tloc(lg->catalog_lid, p);
1285 3266240 : if (lid == lng_nil || lid > tr->tid)
1286 : posnew = p;
1287 1499523 : else if (lid == tr->tid)
1288 3538496 : posold = p;
1289 : }
1290 552494 : MT_rwlock_rdunlock(&cni.b->thashlock);
1291 552494 : bat_iterator_end(&cni);
1292 : /* Normally at this point, posnew is the
1293 : * location of the bat that this
1294 : * transaction is working on, and posold
1295 : * is the location of the previous
1296 : * version of the bat. If LOG_CREATE,
1297 : * both are relevant, since the latter
1298 : * is the new bat, and the former is the
1299 : * to-be-destroyed bat. For
1300 : * LOG_DESTROY, only posnew should be
1301 : * relevant, but for the other types, if
1302 : * the table is destroyed later in the
1303 : * same transaction, we need posold, and
1304 : * else (the normal case) we need
1305 : * posnew. */
1306 552494 : if (posnew != BUN_NONE) {
1307 543790 : assert(posnew < maxupdated);
1308 543790 : updated[posnew / 32] |= 1U << (posnew % 32);
1309 : }
1310 552494 : if ((l.flag == LOG_CREATE || posnew == BUN_NONE) && posold != BUN_NONE) {
1311 161282 : assert(posold < maxupdated);
1312 161282 : updated[posold / 32] |= 1U << (posold % 32);
1313 : }
1314 : }
1315 : break;
1316 : default:
1317 : /* do nothing */
1318 : break;
1319 : }
1320 : /* the functions we call here can succeed (LOG_OK),
1321 : * but they can also fail for two different reasons:
1322 : * they can run out of input (LOG_EOF -- this is not
1323 : * serious, we just abort the remaining transactions),
1324 : * or some malloc or BAT update fails (LOG_ERR -- this
1325 : * is serious, we must abort the complete process);
1326 : * the latter failure causes the current function to
1327 : * return GDK_FAIL */
1328 744375 : switch (l.flag) {
1329 56330 : case LOG_START:
1330 56330 : assert(!lg->flushing || l.id <= lg->tid);
1331 56330 : if (!lg->flushing && l.id > lg->tid)
1332 109 : lg->tid = l.id; /* should only happen during initialization */
1333 56330 : if ((tr = tr_create(tr, l.id)) == NULL) {
1334 0 : TRC_CRITICAL(GDK, "memory allocation failed\n");
1335 0 : err = LOG_ERR;
1336 0 : break;
1337 : }
1338 56330 : TRC_DEBUG(WAL, "tstart %d\n", tr->tid);
1339 : break;
1340 56330 : case LOG_END:
1341 56330 : if (tr == NULL)
1342 : err = LOG_EOF;
1343 56330 : else if (tr->tid != l.id) /* abort record */
1344 0 : tr = tr_abort(lg, tr);
1345 : else
1346 56330 : tr = tr_commit(lg, tr);
1347 : break;
1348 2759 : case LOG_SEQ:
1349 2759 : err = log_read_seq(lg, &l);
1350 2759 : break;
1351 388767 : case LOG_UPDATE_CONST:
1352 : case LOG_UPDATE_BULK:
1353 : case LOG_UPDATE:
1354 388767 : if (tr == NULL)
1355 : err = LOG_EOF;
1356 : else {
1357 610616 : err = log_read_updates(lg, tr, &l, l.id, cands ? &cands : NULL);
1358 : }
1359 : break;
1360 156699 : case LOG_CREATE:
1361 156699 : if (tr == NULL)
1362 : err = LOG_EOF;
1363 : else
1364 156699 : err = log_read_create(lg, tr, l.id);
1365 : break;
1366 8740 : case LOG_DESTROY:
1367 8740 : if (tr == NULL)
1368 : err = LOG_EOF;
1369 : else
1370 8740 : err = log_read_destroy(lg, tr, l.id);
1371 : break;
1372 74750 : case LOG_BAT_GROUP:
1373 74750 : if (tr == NULL)
1374 : err = LOG_EOF;
1375 : else {
1376 74750 : if (l.id > 0) {
1377 : /* START OF LOG_BAT_GROUP */
1378 37375 : cands = COLnew(0, TYPE_void, 0, SYSTRANS);
1379 37375 : if (!cands) {
1380 0 : TRC_CRITICAL(GDK, "creating bat failed\n");
1381 0 : err = LOG_ERR;
1382 : }
1383 37375 : } else if (cands == NULL) {
1384 : /* should have gone through the
1385 : * above option earlier */
1386 0 : TRC_CRITICAL(GDK, "unexpected error\n");
1387 0 : err = LOG_ERR;
1388 : } else {
1389 : /* END OF LOG_BAT_GROUP */
1390 37375 : BBPunfix(cands->batCacheid);
1391 37375 : cands = NULL;
1392 : }
1393 : }
1394 : break;
1395 0 : default:
1396 0 : TRC_CRITICAL(GDK, "unrecognized log entry %d", l.flag);
1397 0 : err = LOG_ERR;
1398 : }
1399 744375 : if (tr == (trans *) -1) {
1400 : /* message already generated by tr_commit */
1401 : err = LOG_ERR;
1402 12382 : tr = NULL;
1403 : break;
1404 : }
1405 : }
1406 12382 : while (tr) {
1407 0 : TRC_WARNING(GDK, "aborting transaction\n");
1408 0 : tr = tr_abort(lg, tr);
1409 : }
1410 12382 : if (!lg->flushing)
1411 141 : ATOMIC_SET(&GDKdebug, dbg);
1412 :
1413 12382 : BBPreclaim(cands);
1414 12382 : if (!ok)
1415 12382 : return LOG_EOF;
1416 : return err;
1417 : }
1418 :
1419 : static gdk_return
1420 235 : log_readlog(logger *lg, const char *filename, bool *filemissing)
1421 : {
1422 235 : log_return err = LOG_OK;
1423 235 : time_t t0, t1;
1424 235 : struct stat sb;
1425 :
1426 235 : assert(!lg->inmemory);
1427 :
1428 235 : TRC_INFO(WAL, "opening %s\n", filename);
1429 :
1430 235 : gdk_return res = log_open_input(lg, filename, filemissing);
1431 235 : if (!lg->input_log || res != GDK_SUCCEED)
1432 : return res;
1433 141 : int fd;
1434 141 : if ((fd = getFileNo(lg->input_log)) < 0 || fstat(fd, &sb) < 0) {
1435 0 : GDKsyserror("fstat on opened file %s failed\n", filename);
1436 0 : log_close_input(lg);
1437 : /* If the file could be opened, but fstat fails,
1438 : * something weird is going on */
1439 0 : return GDK_FAIL;
1440 : }
1441 141 : t0 = time(NULL);
1442 141 : TRC_INFO_IF(WAL) {
1443 0 : TRC_INFO_ENDIF(WAL, "Start reading the write-ahead log '%s'\n", filename);
1444 0 : GDKtracer_flush_buffer();
1445 : }
1446 282 : while (err != LOG_EOF && err != LOG_ERR) {
1447 141 : t1 = time(NULL);
1448 141 : if (t1 - t0 > 10) {
1449 0 : lng fpos;
1450 0 : t0 = t1;
1451 : /* not more than once every 10 seconds */
1452 0 : fpos = (lng) getfilepos(getFile(lg->input_log));
1453 0 : TRC_INFO_IF(WAL) {
1454 0 : if (fpos >= 0) {
1455 0 : TRC_INFO_ENDIF(WAL, "still reading write-ahead log \"%s\" (%d%% done)\n",
1456 : filename, (int) ((fpos * 100 + 50) / sb.st_size));
1457 0 : GDKtracer_flush_buffer();
1458 : }
1459 : }
1460 : }
1461 141 : err = log_read_transaction(lg, NULL, 0);
1462 : }
1463 141 : log_close_input(lg);
1464 141 : lg->input_log = NULL;
1465 :
1466 : /* remaining transactions are not committed, ie abort */
1467 141 : TRC_INFO_IF(WAL) {
1468 0 : TRC_INFO_ENDIF(WAL, "Finished reading the write-ahead log '%s'\n", filename);
1469 0 : GDKtracer_flush_buffer();
1470 : }
1471 : /* we cannot distinguish errors from incomplete transactions
1472 : * (even if we would log aborts in the logs). So we simply
1473 : * abort and move to the next log file */
1474 141 : return err == LOG_ERR ? GDK_FAIL : GDK_SUCCEED;
1475 : }
1476 :
1477 : /*
1478 : * The log files are incrementally numbered, starting from 2. They are
1479 : * processed in the same sequence.
1480 : */
1481 : static gdk_return
1482 89 : log_readlogs(logger *lg, const char *filename)
1483 : {
1484 89 : gdk_return res = GDK_SUCCEED;
1485 :
1486 89 : assert(!lg->inmemory);
1487 89 : TRC_DEBUG(WAL, "logger id is " LLFMT " last logger id is " LLFMT "\n", lg->id, lg->saved_id);
1488 :
1489 89 : char log_filename[FILENAME_MAX];
1490 89 : if (lg->saved_id >= lg->id) {
1491 89 : bool filemissing = false;
1492 :
1493 89 : lg->id = lg->saved_id + 1;
1494 324 : while (res == GDK_SUCCEED && !filemissing) {
1495 235 : if (snprintf(log_filename, sizeof(log_filename), "%s." LLFMT, filename, lg->id) >= FILENAME_MAX) {
1496 0 : GDKerror("Logger filename path is too large\n");
1497 0 : return GDK_FAIL;
1498 : }
1499 235 : res = log_readlog(lg, log_filename, &filemissing);
1500 235 : if (!filemissing) {
1501 146 : lg->saved_id++;
1502 146 : lg->id++;
1503 : }
1504 : }
1505 : }
1506 : return res;
1507 : }
1508 :
1509 : static gdk_return
1510 12412 : log_commit(logger *lg, logged_range *pending, uint32_t *updated, BUN maxupdated)
1511 : {
1512 12412 : TRC_DEBUG(WAL, "commit");
1513 :
1514 12412 : return bm_commit(lg, pending, updated, maxupdated);
1515 : }
1516 :
1517 : static gdk_return
1518 89 : check_version(logger *lg, FILE *fp, bool *needsnew)
1519 : {
1520 89 : int version = 0;
1521 :
1522 89 : assert(!lg->inmemory);
1523 89 : if (fscanf(fp, "%6d", &version) != 1) {
1524 0 : GDKerror("Could not read the version number from the file '%s/log'.\n", lg->dir);
1525 0 : fclose(fp);
1526 0 : return GDK_FAIL;
1527 : }
1528 89 : if (version != lg->version) {
1529 32 : if (lg->prefuncp == NULL ||
1530 16 : (*lg->prefuncp) (lg->funcdata, version, lg->version) != GDK_SUCCEED) {
1531 0 : GDKerror("Incompatible database version %06d, "
1532 : "this server supports version %06d.\n%s",
1533 : version, lg->version,
1534 : version < lg->version ? "Maybe you need to upgrade to an intermediate release first.\n" : "");
1535 0 : fclose(fp);
1536 0 : return GDK_FAIL;
1537 : }
1538 16 : *needsnew = true; /* we need to write a new log file */
1539 : } else {
1540 73 : lg->postfuncp = NULL; /* don't call */
1541 73 : *needsnew = false; /* log file already up-to-date */
1542 : }
1543 178 : if (fgetc(fp) != '\n' || /* skip \n */
1544 89 : fgetc(fp) != '\n') { /* skip \n */
1545 0 : GDKerror("Badly formatted log file");
1546 0 : fclose(fp);
1547 0 : return GDK_FAIL;
1548 : }
1549 89 : if (log_read_types_file(lg, fp, version) != GDK_SUCCEED) {
1550 0 : fclose(fp);
1551 0 : return GDK_FAIL;
1552 : }
1553 89 : fclose(fp);
1554 89 : return GDK_SUCCEED;
1555 : }
1556 :
1557 : static BAT *
1558 354 : bm_tids(BAT *b, BAT *d)
1559 : {
1560 354 : BUN sz = BATcount(b);
1561 354 : BAT *tids = BATdense(0, 0, sz);
1562 :
1563 354 : if (tids == NULL)
1564 : return NULL;
1565 :
1566 354 : if (BATcount(d)) {
1567 354 : BAT *diff = BATdiff(tids, d, NULL, NULL, false, false, BUN_NONE);
1568 354 : logbat_destroy(tids);
1569 354 : tids = diff;
1570 : }
1571 : return tids;
1572 : }
1573 :
1574 :
1575 : static gdk_return
1576 8403 : log_switch_bat(BAT *old, BAT *new, const char *fn, const char *name)
1577 : {
1578 8403 : char bak[IDLENGTH];
1579 :
1580 8403 : if (BATmode(old, true) != GDK_SUCCEED) {
1581 0 : GDKerror("cannot convert old %s to transient", name);
1582 0 : return GDK_FAIL;
1583 : }
1584 8403 : if (strconcat_len(bak, sizeof(bak), fn, "_", name, NULL) >= sizeof(bak)) {
1585 0 : GDKerror("name %s_%s too long\n", fn, name);
1586 0 : return GDK_FAIL;
1587 : }
1588 8403 : if (BBPrename(old, NULL) != 0 || BBPrename(new, bak) != 0) {
1589 0 : GDKerror("rename (%s) failed\n", bak);
1590 0 : return GDK_FAIL;
1591 : }
1592 8403 : BBPretain(new->batCacheid);
1593 8403 : return GDK_SUCCEED;
1594 : }
1595 :
1596 : static gdk_return
1597 315 : bm_get_counts(logger *lg)
1598 : {
1599 315 : BUN p, q;
1600 315 : const log_bid *bids = (const log_bid *) Tloc(lg->catalog_bid, 0);
1601 :
1602 22914 : BATloop(lg->catalog_bid, p, q) {
1603 22599 : oid pos = p;
1604 22599 : lng cnt = 0;
1605 22599 : lng lid = lng_nil;
1606 :
1607 22599 : if (BUNfnd(lg->dcatalog, &pos) == BUN_NONE) {
1608 22599 : BAT *b = BBPquickdesc(bids[p]);
1609 22599 : assert(b);
1610 22599 : cnt = BATcount(b);
1611 : } else {
1612 0 : lid = BBP_desc(bids[p])->batCacheid != 0 && log_find(lg->catalog_bid, lg->dcatalog, bids[p]) == BUN_NONE ? 1 : -1;
1613 : }
1614 22599 : if (BUNappend(lg->catalog_cnt, &cnt, false) != GDK_SUCCEED)
1615 0 : return GDK_FAIL;
1616 22599 : if (BUNappend(lg->catalog_lid, &lid, false) != GDK_SUCCEED)
1617 : return GDK_FAIL;
1618 : }
1619 : return GDK_SUCCEED;
1620 : }
1621 :
1622 : static int
1623 8403 : subcommit_list_add(int next, bat *n, BUN *sizes, bat bid, BUN sz)
1624 : {
1625 8403 : assert(sz <= BBP_desc(bid)->batCount || sz == BUN_NONE);
1626 1905690 : for (int i = 0; i < next; i++) {
1627 1897287 : if (n[i] == bid) {
1628 0 : sizes[i] = sz;
1629 0 : return next;
1630 : }
1631 : }
1632 8403 : n[next] = bid;
1633 8403 : sizes[next++] = sz;
1634 8403 : return next;
1635 : }
1636 :
1637 : static int
1638 2565 : cleanup_and_swap(logger *lg, int *r, const log_bid *bids, lng *lids, lng *cnts,
1639 : BAT *catalog_bid, BAT *catalog_id, BAT *dcatalog, BUN cleanup)
1640 : {
1641 2565 : BAT *nbids, *noids, *ncnts, *nlids, *ndels;
1642 2565 : BUN p, q;
1643 2565 : int err = 0, rcnt = 0;
1644 :
1645 2565 : BUN ocnt = BATcount(catalog_bid);
1646 2565 : nbids = logbat_new(TYPE_int, ocnt - cleanup, PERSISTENT);
1647 2565 : noids = logbat_new(TYPE_int, ocnt - cleanup, PERSISTENT);
1648 2565 : ncnts = logbat_new(TYPE_lng, ocnt - cleanup, SYSTRANS);
1649 2565 : nlids = logbat_new(TYPE_lng, ocnt - cleanup, SYSTRANS);
1650 2565 : ndels = logbat_new(TYPE_oid, BATcount(dcatalog) - cleanup, PERSISTENT);
1651 :
1652 2565 : if (nbids == NULL || noids == NULL || ncnts == NULL || nlids == NULL || ndels == NULL) {
1653 0 : logbat_destroy(nbids);
1654 0 : logbat_destroy(noids);
1655 0 : logbat_destroy(ncnts);
1656 0 : logbat_destroy(nlids);
1657 0 : logbat_destroy(ndels);
1658 0 : return 0;
1659 : }
1660 :
1661 2565 : oid *poss = Tloc(dcatalog, 0);
1662 179313 : BATloop(dcatalog, p, q) {
1663 176748 : oid pos = poss[p];
1664 :
1665 176748 : if (lids[pos] == lng_nil || lids[pos] > lg->saved_tid)
1666 0 : continue;
1667 :
1668 176748 : if (lids[pos] >= 0) {
1669 176748 : bat bid = bids[pos];
1670 176748 : BAT *lb = BBP_desc(bid);
1671 :
1672 176748 : if (lb->batCacheid == 0 || BATmode(lb, true /*transient */ ) != GDK_SUCCEED) {
1673 0 : GDKwarning("Failed to set bat(%d) transient\n", bid);
1674 : } else {
1675 176748 : lids[pos] = -1; /* mark as transient */
1676 176748 : r[rcnt++] = bid;
1677 : }
1678 : }
1679 : }
1680 :
1681 2565 : int *oids = (int *) Tloc(catalog_id, 0);
1682 2565 : q = BATcount(catalog_bid);
1683 901278 : for (p = 0; p < q && !err; p++) {
1684 898713 : bat col = bids[p];
1685 898713 : int nid = oids[p];
1686 898713 : lng lid = lids[p];
1687 898713 : lng cnt = cnts[p];
1688 898713 : oid pos = p;
1689 :
1690 : /* only project out the deleted with lid == -1
1691 : * update dcatalog */
1692 898713 : if (lid == -1)
1693 176748 : continue; /* remove */
1694 :
1695 1443930 : if (BUNappend(nbids, &col, true) != GDK_SUCCEED ||
1696 1443930 : BUNappend(noids, &nid, true) != GDK_SUCCEED ||
1697 1443930 : BUNappend(nlids, &lid, false) != GDK_SUCCEED ||
1698 721965 : BUNappend(ncnts, &cnt, false) != GDK_SUCCEED)
1699 : err = 1;
1700 721965 : if (BUNfnd(lg->dcatalog, &pos) != BUN_NONE) {
1701 0 : pos = (oid) (BATcount(nbids) - 1);
1702 0 : if (BUNappend(ndels, &pos, true) != GDK_SUCCEED)
1703 721965 : err = 1;
1704 : }
1705 : }
1706 :
1707 2565 : if (err) {
1708 0 : logbat_destroy(nbids);
1709 0 : logbat_destroy(noids);
1710 0 : logbat_destroy(ndels);
1711 0 : logbat_destroy(ncnts);
1712 0 : logbat_destroy(nlids);
1713 0 : return 0;
1714 : }
1715 : /* point of no return */
1716 5130 : if (log_switch_bat(catalog_bid, nbids, lg->fn, "catalog_bid") != GDK_SUCCEED ||
1717 5130 : log_switch_bat(catalog_id, noids, lg->fn, "catalog_id") != GDK_SUCCEED ||
1718 2565 : log_switch_bat(dcatalog, ndels, lg->fn, "dcatalog") != GDK_SUCCEED) {
1719 0 : logbat_destroy(nbids);
1720 0 : logbat_destroy(noids);
1721 0 : logbat_destroy(ndels);
1722 0 : logbat_destroy(ncnts);
1723 0 : logbat_destroy(nlids);
1724 0 : return -1;
1725 : }
1726 2565 : r[rcnt++] = lg->catalog_bid->batCacheid;
1727 2565 : r[rcnt++] = lg->catalog_id->batCacheid;
1728 2565 : r[rcnt++] = lg->dcatalog->batCacheid;
1729 :
1730 2565 : assert(BATcount(lg->dcatalog) - cleanup == BATcount(ndels));
1731 :
1732 2565 : logbat_destroy(lg->catalog_bid);
1733 2565 : logbat_destroy(lg->catalog_id);
1734 2565 : logbat_destroy(lg->dcatalog);
1735 :
1736 2565 : lg->catalog_bid = nbids;
1737 2565 : lg->catalog_id = noids;
1738 2565 : lg->dcatalog = ndels;
1739 :
1740 : /* failing to rename these two bats is not fatal */
1741 2565 : if (BBPrename(lg->catalog_cnt, NULL) != GDK_SUCCEED)
1742 2565 : GDKclrerr();
1743 2565 : if (BBPrename(lg->catalog_lid, NULL) != GDK_SUCCEED)
1744 2565 : GDKclrerr();
1745 2565 : BBPunfix(lg->catalog_cnt->batCacheid);
1746 2565 : BBPunfix(lg->catalog_lid->batCacheid);
1747 :
1748 2565 : lg->catalog_cnt = ncnts;
1749 2565 : lg->catalog_lid = nlids;
1750 2565 : char bak[FILENAME_MAX];
1751 2565 : strconcat_len(bak, sizeof(bak), lg->fn, "_catalog_cnt", NULL);
1752 2565 : if (BBPrename(lg->catalog_cnt, bak) < 0)
1753 0 : GDKclrerr();
1754 2565 : strconcat_len(bak, sizeof(bak), lg->fn, "_catalog_lid", NULL);
1755 2565 : if (BBPrename(lg->catalog_lid, bak) < 0)
1756 0 : GDKclrerr();
1757 2565 : rotation_lock(lg);
1758 10648 : for (logged_range *p = lg->pending; p; p = p->next) {
1759 8083 : p->cnt -= cleanup;
1760 : }
1761 2565 : rotation_unlock(lg);
1762 2565 : return rcnt;
1763 : }
1764 :
1765 : /* this function is called with log_lock() held; it releases the lock
1766 : * before returning */
1767 : static gdk_return
1768 12864 : bm_subcommit(logger *lg, logged_range *pending, uint32_t *updated, BUN maxupdated)
1769 : {
1770 12864 : BUN cnt = pending ? pending->cnt : BATcount(lg->catalog_bid);
1771 12864 : BUN dcnt = BATcount(lg->dcatalog);
1772 12864 : BUN p, q;
1773 12864 : BAT *catalog_bid = lg->catalog_bid;
1774 12864 : BAT *catalog_id = lg->catalog_id;
1775 12864 : BAT *dcatalog = lg->dcatalog;
1776 12864 : BUN nn = 13 + cnt;
1777 12864 : bat *n = GDKmalloc(sizeof(bat) * nn);
1778 12864 : bat *r = GDKmalloc(sizeof(bat) * nn);
1779 12864 : BUN *sizes = GDKmalloc(sizeof(BUN) * nn);
1780 12864 : int i = 0, rcnt = 0;
1781 12864 : gdk_return res;
1782 12864 : const log_bid *bids;
1783 12864 : lng *cnts = NULL, *lids = NULL;
1784 12864 : BUN cleanup = 0;
1785 12864 : lng t0 = 0;
1786 :
1787 12864 : if (n == NULL || r == NULL || sizes == NULL) {
1788 0 : GDKfree(n);
1789 0 : GDKfree(r);
1790 0 : GDKfree(sizes);
1791 0 : log_unlock(lg);
1792 0 : return GDK_FAIL;
1793 : }
1794 :
1795 12864 : sizes[i] = 0;
1796 12864 : n[i++] = 0; /* n[0] is not used */
1797 12864 : bids = (const log_bid *) Tloc(catalog_bid, 0);
1798 12864 : if (lg->catalog_cnt)
1799 12638 : cnts = (lng *) Tloc(lg->catalog_cnt, 0);
1800 12864 : if (lg->catalog_lid)
1801 12638 : lids = (lng *) Tloc(lg->catalog_lid, 0);
1802 3763358 : BATloop(catalog_bid, p, q) {
1803 3750494 : if (lids && lids[p] != lng_nil && lids[p] <= lg->saved_tid) {
1804 176748 : cleanup++;
1805 176748 : if (lids[p] == -1)
1806 0 : continue;
1807 353496 : if (BUNfnd(dcatalog, &(oid){p}) == BUN_NONE &&
1808 176748 : BUNappend(dcatalog, &(oid){p}, true) != GDK_SUCCEED) {
1809 0 : while (BATcount(dcatalog) > dcnt) {
1810 0 : if (BUNdelete(dcatalog, BATcount(dcatalog) - 1) != GDK_SUCCEED) {
1811 0 : TRC_CRITICAL(WAL, "delete after failed append failed\n");
1812 0 : break;
1813 : }
1814 : }
1815 0 : GDKfree(n);
1816 0 : GDKfree(r);
1817 0 : GDKfree(sizes);
1818 0 : log_unlock(lg);
1819 0 : return GDK_FAIL;
1820 : }
1821 : }
1822 3750494 : if (updated && p < maxupdated && (updated[p / 32] & (1U << (p % 32))) == 0) {
1823 1860124 : continue;
1824 : }
1825 1890370 : bat col = bids[p];
1826 :
1827 1890370 : TRC_DEBUG(WAL, "new %s (%d)\n", BBP_logical(col), col);
1828 1890370 : assert(col);
1829 1890370 : sizes[i] = cnts ? (BUN) cnts[p] : 0;
1830 1890370 : n[i++] = col;
1831 : }
1832 : /* now commit catalog, so it's also up to date on disk */
1833 12864 : sizes[i] = cnt;
1834 12864 : n[i++] = catalog_bid->batCacheid;
1835 12864 : sizes[i] = cnt;
1836 12864 : n[i++] = catalog_id->batCacheid;
1837 12864 : sizes[i] = BATcount(dcatalog);
1838 12864 : n[i++] = dcatalog->batCacheid;
1839 :
1840 12864 : if (cleanup) {
1841 2565 : if ((rcnt = cleanup_and_swap(lg, r, bids, lids, cnts,
1842 : catalog_bid, catalog_id, dcatalog,
1843 : cleanup)) < 0) {
1844 0 : GDKfree(n);
1845 0 : GDKfree(r);
1846 0 : GDKfree(sizes);
1847 0 : log_unlock(lg);
1848 0 : return GDK_FAIL;
1849 : }
1850 2565 : cnt -= cleanup;
1851 : }
1852 12864 : if (dcatalog != lg->dcatalog) {
1853 2565 : i = subcommit_list_add(i, n, sizes, lg->catalog_bid->batCacheid, cnt);
1854 2565 : i = subcommit_list_add(i, n, sizes, lg->catalog_id->batCacheid, cnt);
1855 2565 : i = subcommit_list_add(i, n, sizes, lg->dcatalog->batCacheid, BATcount(lg->dcatalog));
1856 : }
1857 12864 : if (lg->seqs_id) {
1858 12638 : sizes[i] = BATcount(lg->seqs_id);
1859 12638 : n[i++] = lg->seqs_id->batCacheid;
1860 12638 : sizes[i] = BATcount(lg->seqs_id);
1861 12638 : n[i++] = lg->seqs_val->batCacheid;
1862 : }
1863 12864 : if (!cleanup && lg->seqs_id && BATcount(lg->dseqs) > (BATcount(lg->seqs_id) / 2) && BATcount(lg->dseqs) > 10) {
1864 354 : BAT *tids, *ids, *vals;
1865 :
1866 354 : tids = bm_tids(lg->seqs_id, lg->dseqs);
1867 354 : if (tids == NULL) {
1868 0 : GDKfree(n);
1869 0 : GDKfree(r);
1870 0 : GDKfree(sizes);
1871 0 : log_unlock(lg);
1872 0 : return GDK_FAIL;
1873 : }
1874 354 : ids = logbat_new(TYPE_int, BATcount(tids), PERSISTENT);
1875 354 : vals = logbat_new(TYPE_lng, BATcount(tids), PERSISTENT);
1876 :
1877 354 : if (ids == NULL || vals == NULL) {
1878 0 : logbat_destroy(tids);
1879 0 : logbat_destroy(ids);
1880 0 : logbat_destroy(vals);
1881 0 : GDKfree(n);
1882 0 : GDKfree(r);
1883 0 : GDKfree(sizes);
1884 0 : log_unlock(lg);
1885 0 : return GDK_FAIL;
1886 : }
1887 :
1888 708 : if (BATappend(ids, lg->seqs_id, tids, true) != GDK_SUCCEED ||
1889 354 : BATappend(vals, lg->seqs_val, tids, true) != GDK_SUCCEED) {
1890 0 : logbat_destroy(tids);
1891 0 : logbat_destroy(ids);
1892 0 : logbat_destroy(vals);
1893 0 : GDKfree(n);
1894 0 : GDKfree(r);
1895 0 : GDKfree(sizes);
1896 0 : log_unlock(lg);
1897 0 : return GDK_FAIL;
1898 : }
1899 354 : logbat_destroy(tids);
1900 354 : BATclear(lg->dseqs, true);
1901 :
1902 708 : if (log_switch_bat(lg->seqs_id, ids, lg->fn, "seqs_id") != GDK_SUCCEED ||
1903 354 : log_switch_bat(lg->seqs_val, vals, lg->fn, "seqs_val") != GDK_SUCCEED) {
1904 0 : logbat_destroy(ids);
1905 0 : logbat_destroy(vals);
1906 0 : GDKfree(n);
1907 0 : GDKfree(r);
1908 0 : GDKfree(sizes);
1909 0 : log_unlock(lg);
1910 0 : return GDK_FAIL;
1911 : }
1912 354 : i = subcommit_list_add(i, n, sizes, ids->batCacheid, BATcount(ids));
1913 354 : i = subcommit_list_add(i, n, sizes, vals->batCacheid, BATcount(ids));
1914 :
1915 354 : if (BBP_lrefs(lg->seqs_id->batCacheid) > 0)
1916 283 : r[rcnt++] = lg->seqs_id->batCacheid;
1917 354 : if (BBP_lrefs(lg->seqs_val->batCacheid) > 0)
1918 283 : r[rcnt++] = lg->seqs_val->batCacheid;
1919 :
1920 354 : logbat_destroy(lg->seqs_id);
1921 354 : logbat_destroy(lg->seqs_val);
1922 :
1923 354 : lg->seqs_id = ids;
1924 354 : lg->seqs_val = vals;
1925 : }
1926 12864 : if (lg->seqs_id) {
1927 12638 : sizes[i] = BATcount(lg->dseqs);
1928 12638 : n[i++] = lg->dseqs->batCacheid;
1929 : }
1930 :
1931 12864 : assert((BUN) i <= nn);
1932 12864 : log_unlock(lg);
1933 12864 : TRC_DEBUG_IF(WAL)
1934 0 : t0 = GDKusec();
1935 13090 : res = TMsubcommit_list(n, cnts ? sizes : NULL, i, lg->saved_id);
1936 12864 : TRC_DEBUG(WAL, "subcommit " LLFMT "usec\n", GDKusec() - t0);
1937 12864 : if (res == GDK_SUCCEED) { /* now cleanup */
1938 197873 : for (i = 0; i < rcnt; i++) {
1939 185009 : TRC_DEBUG_IF(WAL) {
1940 0 : TRC_DEBUG_ENDIF(WAL, "release %d\n", r[i]);
1941 0 : if (BBP_lrefs(r[i]) != 2)
1942 0 : TRC_DEBUG_ENDIF(WAL, "release %d %d\n", r[i], BBP_lrefs(r[i]));
1943 : }
1944 185009 : BBPrelease(r[i]);
1945 : }
1946 : }
1947 12864 : GDKfree(n);
1948 12864 : GDKfree(r);
1949 12864 : GDKfree(sizes);
1950 12864 : if (res != GDK_SUCCEED)
1951 0 : TRC_CRITICAL(GDK, "commit failed\n");
1952 : return res;
1953 : }
1954 :
1955 : static gdk_return
1956 314 : log_filename(logger *lg, char bak[FILENAME_MAX], char filename[FILENAME_MAX])
1957 : {
1958 314 : str filenamestr = NULL;
1959 :
1960 314 : if ((filenamestr = GDKfilepath(0, lg->dir, LOGFILE, NULL)) == NULL)
1961 : return GDK_FAIL;
1962 314 : size_t len = strcpy_len(filename, filenamestr, FILENAME_MAX);
1963 314 : GDKfree(filenamestr);
1964 314 : if (len >= FILENAME_MAX) {
1965 0 : GDKerror("Logger filename path is too large\n");
1966 0 : return GDK_FAIL;
1967 : }
1968 314 : if (bak) {
1969 314 : len = strconcat_len(bak, FILENAME_MAX, filename, ".bak", NULL);
1970 314 : if (len >= FILENAME_MAX) {
1971 0 : GDKerror("Logger filename path is too large\n");
1972 0 : return GDK_FAIL;
1973 : }
1974 : }
1975 : return GDK_SUCCEED;
1976 : }
1977 :
1978 : static gdk_return
1979 12387 : log_cleanup(logger *lg, lng id)
1980 : {
1981 12387 : char log_id[FILENAME_MAX];
1982 :
1983 12387 : if (snprintf(log_id, sizeof(log_id), LLFMT, id) >= FILENAME_MAX) {
1984 0 : GDKerror("log_id filename is too large\n");
1985 0 : return GDK_FAIL;
1986 : }
1987 12387 : if (GDKunlink(0, lg->dir, LOGFILE, log_id) != GDK_SUCCEED) {
1988 0 : GDKwarning("failed to remove old WAL %s.%s\n", LOGFILE, log_id);
1989 0 : GDKclrerr(); /* clear error from unlink */
1990 : }
1991 : return GDK_SUCCEED;
1992 : }
1993 :
1994 : #ifdef GDKLIBRARY_JSON
1995 : static gdk_return
1996 315 : log_json_upgrade_finalize(void)
1997 : {
1998 315 : int json_tpe = ATOMindex("json");
1999 629 : if (!GDKinmemory(0) &&
2000 314 : GDKunlink(0, BATDIR, "jsonupgradeneeded", NULL) == GDK_FAIL) {
2001 0 : TRC_CRITICAL(GDK, "Failed to remove json upgrade signal file");
2002 0 : return GDK_FAIL;
2003 : }
2004 315 : BATatoms[json_tpe].atomRead = (void *(*)(void *, size_t *, stream *, size_t))strRead;
2005 :
2006 315 : return GDK_SUCCEED;
2007 : }
2008 : #endif
2009 :
2010 : /* Load data from the logger logdir
2011 : * Initialize new directories and catalog files if none are present,
2012 : * unless running in read-only mode
2013 : * Load data and persist it in the BATs */
2014 : static gdk_return
2015 315 : log_load(const char *fn, logger *lg, char filename[FILENAME_MAX])
2016 : {
2017 315 : FILE *fp = NULL;
2018 315 : char bak[FILENAME_MAX];
2019 315 : bat catalog_bid, catalog_id, dcatalog;
2020 315 : bool needcommit = false;
2021 315 : ATOMIC_BASE_TYPE dbg = ATOMIC_GET(&GDKdebug);
2022 315 : bool readlogs = false;
2023 315 : bool needsnew = false; /* need to write new log file? */
2024 :
2025 : /* refactor */
2026 315 : if (!LOG_DISABLED(lg)) {
2027 314 : if (log_filename(lg, bak, filename) != GDK_SUCCEED)
2028 0 : goto error;
2029 : }
2030 :
2031 315 : lg->catalog_bid = NULL;
2032 315 : lg->catalog_id = NULL;
2033 315 : lg->catalog_cnt = NULL;
2034 315 : lg->catalog_lid = NULL;
2035 315 : lg->dcatalog = NULL;
2036 :
2037 315 : lg->seqs_id = NULL;
2038 315 : lg->seqs_val = NULL;
2039 315 : lg->dseqs = NULL;
2040 :
2041 315 : if (!LOG_DISABLED(lg)) {
2042 : /* try to open logfile backup, or failing that, the file
2043 : * itself. we need to know whether this file exists when
2044 : * checking the database consistency later on */
2045 314 : if ((fp = MT_fopen(bak, "r")) != NULL) {
2046 0 : fclose(fp);
2047 0 : fp = NULL;
2048 0 : if (GDKunlink(0, lg->dir, LOGFILE, NULL) != GDK_SUCCEED ||
2049 0 : GDKmove(0, lg->dir, LOGFILE, "bak", lg->dir, LOGFILE, NULL, true) != GDK_SUCCEED)
2050 0 : goto error;
2051 314 : } else if (errno != ENOENT) {
2052 0 : GDKsyserror("open %s failed", bak);
2053 0 : goto error;
2054 : }
2055 314 : fp = MT_fopen(filename, "r");
2056 314 : if (fp == NULL && errno != ENOENT) {
2057 0 : GDKsyserror("open %s failed", filename);
2058 0 : goto error;
2059 : }
2060 : }
2061 :
2062 315 : strconcat_len(bak, sizeof(bak), fn, "_catalog_bid", NULL);
2063 315 : catalog_bid = BBPindex(bak);
2064 :
2065 : /* initialize arrays for type mapping, to be read from disk */
2066 315 : memset(lg->type_id, -1, sizeof(lg->type_id));
2067 315 : memset(lg->type_nr, 255, sizeof(lg->type_nr));
2068 :
2069 : /* this is intentional - if catalog_bid is 0, force it to find
2070 : * the persistent catalog */
2071 315 : if (catalog_bid == 0) {
2072 : /* catalog does not exist, so the log file also
2073 : * shouldn't exist */
2074 226 : if (fp != NULL) {
2075 0 : GDKerror("there is no logger catalog, "
2076 : "but there is a log file.\n");
2077 0 : goto error;
2078 : }
2079 :
2080 226 : lg->catalog_bid = logbat_new(TYPE_int, BATSIZE, PERSISTENT);
2081 226 : lg->catalog_id = logbat_new(TYPE_int, BATSIZE, PERSISTENT);
2082 226 : lg->dcatalog = logbat_new(TYPE_oid, BATSIZE, PERSISTENT);
2083 :
2084 226 : if (lg->catalog_bid == NULL || lg->catalog_id == NULL || lg->dcatalog == NULL) {
2085 0 : GDKerror("cannot create catalog bats");
2086 0 : goto error;
2087 : }
2088 226 : TRC_INFO(WAL, "create %s catalog\n", fn);
2089 :
2090 : /* give the catalog bats names so we can find them
2091 : * next time */
2092 226 : strconcat_len(bak, sizeof(bak), fn, "_catalog_bid", NULL);
2093 226 : if (BBPrename(lg->catalog_bid, bak) < 0) {
2094 0 : goto error;
2095 : }
2096 :
2097 226 : strconcat_len(bak, sizeof(bak), fn, "_catalog_id", NULL);
2098 226 : if (BBPrename(lg->catalog_id, bak) < 0) {
2099 0 : goto error;
2100 : }
2101 :
2102 226 : strconcat_len(bak, sizeof(bak), fn, "_dcatalog", NULL);
2103 226 : if (BBPrename(lg->dcatalog, bak) < 0) {
2104 0 : goto error;
2105 : }
2106 :
2107 226 : if (!LOG_DISABLED(lg)) {
2108 225 : if (GDKcreatedir(filename) != GDK_SUCCEED) {
2109 0 : GDKerror("cannot create directory for log file %s\n", filename);
2110 0 : goto error;
2111 : }
2112 225 : if (log_create_types_file(lg, filename) != GDK_SUCCEED)
2113 0 : goto error;
2114 : }
2115 :
2116 226 : BBPretain(lg->catalog_bid->batCacheid);
2117 226 : BBPretain(lg->catalog_id->batCacheid);
2118 226 : BBPretain(lg->dcatalog->batCacheid);
2119 :
2120 226 : log_lock(lg);
2121 : /* bm_subcommit releases the lock */
2122 226 : if (bm_subcommit(lg, NULL, NULL, 0) != GDK_SUCCEED) {
2123 : /* cannot commit catalog, so remove log */
2124 0 : if (MT_remove(filename) < 0)
2125 0 : GDKsyserror("remove %s failed\n", filename);
2126 0 : BBPrelease(lg->catalog_bid->batCacheid);
2127 0 : BBPrelease(lg->catalog_id->batCacheid);
2128 0 : BBPrelease(lg->dcatalog->batCacheid);
2129 0 : goto error;
2130 : }
2131 : } else {
2132 : /* find the persistent catalog. As non persistent bats
2133 : * require a logical reference we also add a logical
2134 : * reference for the persistent bats */
2135 89 : BUN p, q;
2136 89 : BAT *b, *o, *d;
2137 :
2138 89 : assert(!lg->inmemory);
2139 :
2140 : /* the catalog exists, and so should the log file */
2141 89 : if (fp == NULL && !LOG_DISABLED(lg)) {
2142 0 : GDKerror("There is a logger catalog, but no log file.\n");
2143 0 : goto error;
2144 : }
2145 : if (fp != NULL) {
2146 : /* check_version always closes fp */
2147 89 : if (check_version(lg, fp, &needsnew) != GDK_SUCCEED) {
2148 0 : fp = NULL;
2149 0 : goto error;
2150 : }
2151 : readlogs = true;
2152 : fp = NULL;
2153 : }
2154 :
2155 89 : if (lg->catalog_bid == NULL && lg->catalog_id == NULL && lg->dcatalog == NULL) {
2156 89 : b = BATdescriptor(catalog_bid);
2157 89 : if (b == NULL) {
2158 0 : GDKerror("inconsistent database, catalog does not exist");
2159 0 : goto error;
2160 : }
2161 :
2162 89 : strconcat_len(bak, sizeof(bak), fn, "_catalog_id", NULL);
2163 89 : catalog_id = BBPindex(bak);
2164 89 : o = BATdescriptor(catalog_id);
2165 89 : if (o == NULL) {
2166 0 : BBPunfix(b->batCacheid);
2167 0 : GDKerror("inconsistent database, catalog_id does not exist");
2168 0 : goto error;
2169 : }
2170 :
2171 89 : strconcat_len(bak, sizeof(bak), fn, "_dcatalog", NULL);
2172 89 : dcatalog = BBPindex(bak);
2173 89 : d = BATdescriptor(dcatalog);
2174 89 : if (d == NULL) {
2175 0 : GDKerror("cannot create dcatalog bat");
2176 0 : BBPunfix(b->batCacheid);
2177 0 : BBPunfix(o->batCacheid);
2178 0 : goto error;
2179 : }
2180 :
2181 89 : lg->catalog_bid = b;
2182 89 : lg->catalog_id = o;
2183 89 : lg->dcatalog = d;
2184 89 : const log_bid *bids = (const log_bid *) Tloc(lg->catalog_bid, 0);
2185 22688 : BATloop(lg->catalog_bid, p, q) {
2186 22599 : bat bid = bids[p];
2187 22599 : oid pos = p;
2188 :
2189 22599 : if (BBPretain(bid) == 0 && /* any bid in the catalog_bid, needs one logical ref */
2190 0 : BUNfnd(lg->dcatalog, &pos) == BUN_NONE &&
2191 0 : BUNappend(lg->dcatalog, &pos, true) != GDK_SUCCEED)
2192 0 : goto error;
2193 : }
2194 : }
2195 89 : if ((lg->catalog_bid = BATsetaccess(lg->catalog_bid, BAT_READ)) == NULL ||
2196 89 : (lg->catalog_id = BATsetaccess(lg->catalog_id, BAT_READ)) == NULL ||
2197 89 : (lg->dcatalog = BATsetaccess(lg->dcatalog, BAT_READ)) == NULL) {
2198 0 : goto error;
2199 : }
2200 89 : BBPretain(lg->catalog_bid->batCacheid);
2201 89 : BBPretain(lg->catalog_id->batCacheid);
2202 89 : BBPretain(lg->dcatalog->batCacheid);
2203 : }
2204 : /* failing to rename the catalog_cnt and catalog_lid bats is not
2205 : * fatal */
2206 315 : lg->catalog_cnt = logbat_new(TYPE_lng, 1, SYSTRANS);
2207 315 : if (lg->catalog_cnt == NULL) {
2208 0 : GDKerror("failed to create catalog_cnt bat");
2209 0 : goto error;
2210 : }
2211 315 : strconcat_len(bak, sizeof(bak), fn, "_catalog_cnt", NULL);
2212 315 : if (BBPrename(lg->catalog_cnt, bak) < 0)
2213 0 : GDKclrerr();
2214 315 : lg->catalog_lid = logbat_new(TYPE_lng, 1, SYSTRANS);
2215 315 : if (lg->catalog_lid == NULL) {
2216 0 : GDKerror("failed to create catalog_lid bat");
2217 0 : goto error;
2218 : }
2219 315 : strconcat_len(bak, sizeof(bak), fn, "_catalog_lid", NULL);
2220 315 : if (BBPrename(lg->catalog_lid, bak) < 0)
2221 0 : GDKclrerr();
2222 315 : if (bm_get_counts(lg) != GDK_SUCCEED)
2223 0 : goto error;
2224 :
2225 315 : strconcat_len(bak, sizeof(bak), fn, "_seqs_id", NULL);
2226 315 : if (BBPindex(bak)) {
2227 89 : lg->seqs_id = BATdescriptor(BBPindex(bak));
2228 89 : strconcat_len(bak, sizeof(bak), fn, "_seqs_val", NULL);
2229 89 : lg->seqs_val = BATdescriptor(BBPindex(bak));
2230 89 : strconcat_len(bak, sizeof(bak), fn, "_dseqs", NULL);
2231 89 : lg->dseqs = BATdescriptor(BBPindex(bak));
2232 89 : if (lg->seqs_id == NULL ||
2233 89 : lg->seqs_val == NULL ||
2234 : lg->dseqs == NULL) {
2235 0 : GDKerror("Logger_new: cannot load seqs bats");
2236 0 : goto error;
2237 : }
2238 89 : if ((lg->seqs_val = BATsetaccess(lg->seqs_val, BAT_READ)) == NULL ||
2239 89 : (lg->seqs_id = BATsetaccess(lg->seqs_id, BAT_READ)) == NULL ||
2240 89 : (lg->dseqs = BATsetaccess(lg->dseqs, BAT_READ)) == NULL) {
2241 0 : goto error;
2242 : }
2243 : } else {
2244 226 : lg->seqs_id = logbat_new(TYPE_int, 1, PERSISTENT);
2245 226 : lg->seqs_val = logbat_new(TYPE_lng, 1, PERSISTENT);
2246 226 : lg->dseqs = logbat_new(TYPE_oid, 1, PERSISTENT);
2247 226 : if (lg->seqs_id == NULL ||
2248 226 : lg->seqs_val == NULL ||
2249 : lg->dseqs == NULL) {
2250 0 : GDKerror("Logger_new: cannot create seqs bats");
2251 0 : goto error;
2252 : }
2253 :
2254 226 : strconcat_len(bak, sizeof(bak), fn, "_seqs_id", NULL);
2255 226 : if (BBPrename(lg->seqs_id, bak) < 0) {
2256 0 : goto error;
2257 : }
2258 :
2259 226 : strconcat_len(bak, sizeof(bak), fn, "_seqs_val", NULL);
2260 226 : if (BBPrename(lg->seqs_val, bak) < 0) {
2261 0 : goto error;
2262 : }
2263 :
2264 226 : strconcat_len(bak, sizeof(bak), fn, "_dseqs", NULL);
2265 226 : if (BBPrename(lg->dseqs, bak) < 0) {
2266 0 : goto error;
2267 : }
2268 : needcommit = true;
2269 : }
2270 315 : dbg = ATOMIC_GET(&GDKdebug);
2271 315 : ATOMIC_AND(&GDKdebug, ~CHECKMASK);
2272 315 : if (needcommit && bm_commit(lg, NULL, NULL, 0) != GDK_SUCCEED) {
2273 0 : GDKerror("Logger_new: commit failed");
2274 0 : goto error;
2275 : }
2276 315 : ATOMIC_SET(&GDKdebug, dbg);
2277 :
2278 315 : if (readlogs) {
2279 89 : ulng log_id = lg->saved_id + 1;
2280 89 : if (log_readlogs(lg, filename) != GDK_SUCCEED) {
2281 0 : goto error;
2282 : }
2283 89 : if (GDKgetenv_isyes("process-wal-and-exit")) {
2284 0 : printf("# mserver5 exiting\n");
2285 0 : exit(0);
2286 : }
2287 89 : if (lg->postfuncp && (*lg->postfuncp) (lg->funcdata, lg) != GDK_SUCCEED)
2288 0 : goto error;
2289 89 : if (needsnew) {
2290 16 : if (GDKmove(0, lg->dir, LOGFILE, NULL, lg->dir, LOGFILE, "bak", true) != GDK_SUCCEED) {
2291 0 : TRC_CRITICAL(GDK, "couldn't move log to log.bak\n");
2292 0 : return GDK_FAIL;
2293 : }
2294 16 : if (log_create_types_file(lg, filename) != GDK_SUCCEED) {
2295 0 : TRC_CRITICAL(GDK, "couldn't write new log\n");
2296 0 : return GDK_FAIL;
2297 : }
2298 : }
2299 89 : dbg = ATOMIC_GET(&GDKdebug);
2300 89 : ATOMIC_AND(&GDKdebug, ~CHECKMASK);
2301 89 : if (log_commit(lg, NULL, NULL, 0) != GDK_SUCCEED) {
2302 0 : goto error;
2303 : }
2304 89 : ATOMIC_SET(&GDKdebug, dbg);
2305 235 : for (; log_id <= lg->saved_id; log_id++)
2306 146 : (void) log_cleanup(lg, log_id); /* ignore error of removing file */
2307 105 : if (needsnew &&
2308 16 : GDKunlink(0, lg->dir, LOGFILE, "bak") != GDK_SUCCEED) {
2309 0 : TRC_CRITICAL(GDK, "couldn't remove old log.bak file\n");
2310 0 : return GDK_FAIL;
2311 : }
2312 : } else {
2313 226 : lg->id = lg->saved_id + 1;
2314 226 : if (GDKgetenv_isyes("process-wal-and-exit")) {
2315 0 : printf("# mserver5 exiting\n");
2316 0 : exit(0);
2317 : }
2318 : }
2319 : #ifdef GDKLIBRARY_JSON
2320 315 : if (log_json_upgrade_finalize() == GDK_FAIL)
2321 0 : goto error;
2322 : #endif
2323 : return GDK_SUCCEED;
2324 0 : error:
2325 0 : if (fp)
2326 0 : fclose(fp);
2327 0 : logbat_destroy(lg->catalog_bid);
2328 0 : logbat_destroy(lg->catalog_id);
2329 0 : logbat_destroy(lg->dcatalog);
2330 0 : logbat_destroy(lg->seqs_id);
2331 0 : logbat_destroy(lg->seqs_val);
2332 0 : logbat_destroy(lg->dseqs);
2333 0 : MT_lock_destroy(&lg->lock);
2334 0 : MT_lock_destroy(&lg->rotation_lock);
2335 0 : GDKfree(lg->fn);
2336 0 : GDKfree(lg->dir);
2337 0 : GDKfree(lg->rbuf);
2338 0 : GDKfree(lg->wbuf);
2339 0 : GDKfree(lg);
2340 0 : ATOMIC_SET(&GDKdebug, dbg);
2341 : /* We do not call log_json_upgrade_finalize here because we want
2342 : * the upgrade to run again next time we try, so we do not want
2343 : * to remove the signal file just yet.
2344 : */
2345 0 : return GDK_FAIL;
2346 : }
2347 :
2348 : /* Initialize a new logger
2349 : * It will load any data in the logdir and persist it in the BATs*/
2350 : static logger *
2351 315 : log_new(int debug, const char *fn, const char *logdir, int version, preversionfix_fptr prefuncp,
2352 : postversionfix_fptr postfuncp, void *funcdata)
2353 : {
2354 315 : logger *lg;
2355 315 : char filename[FILENAME_MAX];
2356 :
2357 315 : lng max_dropped = GDKgetenv_int("wal_max_dropped", 100000);
2358 315 : lng max_file_age = GDKgetenv_int("wal_max_file_age", 600);
2359 315 : lng max_file_size = 0;
2360 :
2361 315 : if (GDKdebug & TESTINGMASK) {
2362 : max_file_size = 2048; /* 2 KiB */
2363 : } else {
2364 12 : const char *max_file_size_str = GDKgetenv("wal_max_file_size");
2365 12 : max_file_size = max_file_size_str ? strtoul(max_file_size_str, NULL, 10) : 2147483648;
2366 : }
2367 :
2368 315 : if (!GDKinmemory(0) && MT_path_absolute(logdir)) {
2369 0 : TRC_CRITICAL(GDK, "logdir must be relative path\n");
2370 0 : return NULL;
2371 : }
2372 :
2373 315 : if (snprintf(filename, sizeof(filename), "%s%c%s%c", logdir, DIR_SEP, fn, DIR_SEP) >= FILENAME_MAX) {
2374 0 : TRC_CRITICAL(GDK, "filename is too large\n");
2375 0 : return NULL;
2376 : }
2377 :
2378 315 : lg = GDKmalloc(sizeof(struct logger));
2379 315 : if (lg == NULL) {
2380 0 : TRC_CRITICAL(GDK, "allocating logger structure failed\n");
2381 0 : return NULL;
2382 : }
2383 :
2384 630 : *lg = (logger) {
2385 315 : .inmemory = GDKinmemory(0),
2386 : .debug = debug,
2387 : .version = version,
2388 : .prefuncp = prefuncp,
2389 : .postfuncp = postfuncp,
2390 : .funcdata = funcdata,
2391 :
2392 315 : .max_dropped = max_dropped >= 0 ? max_dropped : 100000,
2393 : .file_age = 0,
2394 315 : .max_file_age = max_file_age >= 0 ? max_file_age * 1000000 : 600000000,
2395 315 : .max_file_size = max_file_size >= 0 ? max_file_size : 2147483648,
2396 :
2397 : .id = 0,
2398 315 : .saved_id = getBBPlogno(), /* get saved log number from bbp */
2399 : .nr_flushers = ATOMIC_VAR_INIT(0),
2400 315 : .fn = GDKstrdup(fn),
2401 315 : .dir = GDKstrdup(filename),
2402 : .rbufsize = 64 * 1024,
2403 315 : .rbuf = GDKmalloc(64 * 1024),
2404 : .wbufsize = 64 * 1024,
2405 315 : .wbuf = GDKmalloc(64 * 1024),
2406 : };
2407 :
2408 : /* probably open file and check version first, then call call old logger code */
2409 315 : if (lg->fn == NULL ||
2410 315 : lg->dir == NULL ||
2411 315 : lg->rbuf == NULL ||
2412 : lg->wbuf == NULL) {
2413 0 : TRC_CRITICAL(GDK, "allocating for logger structure failed\n");
2414 0 : GDKfree(lg->fn);
2415 0 : GDKfree(lg->dir);
2416 0 : GDKfree(lg->rbuf);
2417 0 : GDKfree(lg->wbuf);
2418 0 : GDKfree(lg);
2419 0 : return NULL;
2420 : }
2421 315 : TRC_DEBUG(WAL, "dir set to %s\n", lg->dir);
2422 :
2423 315 : MT_lock_init(&lg->lock, fn);
2424 315 : MT_lock_init(&lg->rotation_lock, "rotation_lock");
2425 315 : MT_lock_init(&lg->flush_lock, "flush_lock");
2426 315 : MT_cond_init(&lg->excl_flush_cv);
2427 :
2428 315 : if (log_load(fn, lg, filename) == GDK_SUCCEED) {
2429 : return lg;
2430 : }
2431 : return NULL;
2432 : }
2433 :
2434 : static logged_range *
2435 68324 : do_flush_range_cleanup(logger *lg)
2436 : {
2437 68324 : logged_range *frange = lg->flush_ranges;
2438 68324 : logged_range *first = frange;
2439 :
2440 68324 : if (frange == NULL)
2441 : return NULL;
2442 80658 : while (frange->next) {
2443 12775 : if (ATOMIC_GET(&frange->refcount) > 1)
2444 : break;
2445 12334 : frange = frange->next;
2446 : }
2447 68324 : if (first == frange) {
2448 : return first;
2449 : }
2450 :
2451 12334 : logged_range *flast = frange;
2452 :
2453 12334 : lg->flush_ranges = flast;
2454 :
2455 24668 : for (frange = first; frange && frange != flast; frange = frange->next) {
2456 12334 : ATOMIC_DEC(&frange->refcount);
2457 12334 : if (!LOG_DISABLED(lg) && frange->output_log) {
2458 0 : TRC_INFO(WAL, "closing output log %s", mnstr_name(frange->output_log));
2459 0 : close_stream(frange->output_log);
2460 0 : frange->output_log = NULL;
2461 : }
2462 : }
2463 : return flast;
2464 : }
2465 :
2466 : void
2467 298 : log_destroy(logger *lg)
2468 : {
2469 298 : log_close_input(lg);
2470 298 : logged_range *last = do_flush_range_cleanup(lg);
2471 298 : (void) last;
2472 298 : assert(last == lg->current && last == lg->flush_ranges);
2473 298 : log_close_output(lg);
2474 673 : for (logged_range * p = lg->pending; p; p = lg->pending) {
2475 375 : lg->pending = p->next;
2476 375 : GDKfree(p);
2477 : }
2478 298 : if (LOG_DISABLED(lg)) {
2479 1 : lg->saved_id = lg->id;
2480 1 : lg->saved_tid = lg->tid;
2481 1 : log_commit(lg, NULL, NULL, 0);
2482 : }
2483 298 : if (lg->catalog_bid) {
2484 298 : log_lock(lg);
2485 298 : BUN p, q;
2486 298 : BAT *b = lg->catalog_bid;
2487 :
2488 : /* free resources */
2489 298 : const log_bid *bids = (const log_bid *) Tloc(b, 0);
2490 77889 : BATloop(b, p, q) {
2491 77591 : bat bid = bids[p];
2492 :
2493 77591 : BBPrelease(bid);
2494 : }
2495 :
2496 298 : BBPrelease(lg->catalog_bid->batCacheid);
2497 298 : BBPrelease(lg->catalog_id->batCacheid);
2498 298 : BBPrelease(lg->dcatalog->batCacheid);
2499 298 : logbat_destroy(lg->catalog_bid);
2500 298 : logbat_destroy(lg->catalog_id);
2501 298 : logbat_destroy(lg->dcatalog);
2502 :
2503 298 : logbat_destroy(lg->catalog_cnt);
2504 298 : logbat_destroy(lg->catalog_lid);
2505 298 : log_unlock(lg);
2506 : }
2507 298 : MT_lock_destroy(&lg->lock);
2508 298 : MT_lock_destroy(&lg->rotation_lock);
2509 298 : MT_lock_destroy(&lg->flush_lock);
2510 298 : GDKfree(lg->fn);
2511 298 : GDKfree(lg->dir);
2512 298 : GDKfree(lg->rbuf);
2513 298 : GDKfree(lg->wbuf);
2514 298 : GDKfree(lg);
2515 298 : }
2516 :
2517 : /* Create a new logger */
2518 : logger *
2519 315 : log_create(int debug, const char *fn, const char *logdir, int version,
2520 : preversionfix_fptr prefuncp, postversionfix_fptr postfuncp,
2521 : void *funcdata)
2522 : {
2523 315 : logger *lg;
2524 315 : TRC_INFO_IF(WAL) {
2525 0 : TRC_INFO_ENDIF(WAL, "Started processing logs %s/%s version %d\n", fn, logdir, version);
2526 0 : GDKtracer_flush_buffer();
2527 : }
2528 315 : lg = log_new(debug, fn, logdir, version, prefuncp, postfuncp, funcdata);
2529 315 : if (lg == NULL)
2530 : return NULL;
2531 315 : TRC_INFO_IF(WAL) {
2532 0 : TRC_INFO_ENDIF(WAL, "Finished processing logs %s/%s\n", fn, logdir);
2533 0 : GDKtracer_flush_buffer();
2534 : }
2535 315 : if (GDKsetenv("recovery", "finished") != GDK_SUCCEED) {
2536 0 : log_destroy(lg);
2537 0 : return NULL;
2538 : }
2539 315 : assert(lg->current == NULL);
2540 315 : logged_range dummy = {
2541 315 : .cnt = BATcount(lg->catalog_bid),
2542 : };
2543 315 : lg->current = &dummy;
2544 315 : if (log_open_output(lg) != GDK_SUCCEED) {
2545 0 : lg->current = NULL;
2546 0 : log_destroy(lg);
2547 0 : return NULL;
2548 : }
2549 315 : lg->current = lg->current->next;
2550 315 : assert(lg->pending == NULL && lg->flush_ranges == NULL);
2551 315 : lg->pending = lg->current;
2552 315 : lg->flush_ranges = lg->current;
2553 315 : return lg;
2554 : }
2555 :
2556 : static logged_range *
2557 7968 : log_next_logfile(logger *lg, ulng ts)
2558 : {
2559 7968 : int m = (ATOMIC_GET(&GDKdebug) & TESTINGMASK) ? 1000 : 100;
2560 7968 : if (!lg->pending || !lg->pending->next)
2561 : return NULL;
2562 7968 : rotation_lock(lg);
2563 7968 : if (ATOMIC_GET(&lg->pending->refcount) == 0 && lg->pending != lg->current && lg->pending != lg->flush_ranges &&
2564 7968 : (ulng) ATOMIC_GET(&lg->pending->last_ts) == (ulng) ATOMIC_GET(&lg->pending->flushed_ts) &&
2565 7968 : (ulng) ATOMIC_GET(&lg->pending->flushed_ts) <= ts) {
2566 6688 : rotation_unlock(lg);
2567 6688 : logged_range *p = lg->pending;
2568 6688 : for (int i = 1;
2569 12241 : i < m && ATOMIC_GET(&p->refcount) == 0 && p->next && p->next != lg->current &&
2570 5575 : p->next != lg->flush_ranges && (ulng) ATOMIC_GET(&p->last_ts) == (ulng) ATOMIC_GET(&p->flushed_ts)
2571 17814 : && (ulng) ATOMIC_GET(&p->flushed_ts) <= ts; i++)
2572 5553 : p = p->next;
2573 6688 : return p;
2574 : }
2575 1280 : rotation_unlock(lg);
2576 1280 : return NULL;
2577 : }
2578 :
2579 : static void
2580 6688 : log_cleanup_range(logger *lg, ulng id)
2581 : {
2582 6688 : rotation_lock(lg);
2583 18929 : while (lg->pending && lg->pending->id <= id) {
2584 12241 : logged_range *p;
2585 12241 : p = lg->pending;
2586 12241 : if (p)
2587 12241 : lg->pending = p->next;
2588 12241 : GDKfree(p);
2589 : }
2590 6688 : rotation_unlock(lg);
2591 6688 : }
2592 :
2593 : static void
2594 68029 : do_rotate(logger *lg)
2595 : {
2596 68029 : logged_range *cur = lg->current;
2597 68029 : logged_range *next = cur->next;
2598 68029 : if (next) {
2599 12334 : assert(ATOMIC_GET(&next->refcount) == 1);
2600 12334 : lg->current = next;
2601 12334 : if (!LOG_DISABLED(lg) && ATOMIC_GET(&cur->refcount) == 1 && cur->output_log) {
2602 12141 : close_stream(cur->output_log);
2603 12141 : cur->output_log = NULL;
2604 : }
2605 : }
2606 68029 : }
2607 :
2608 : gdk_return
2609 10241 : log_activate(logger *lg)
2610 : {
2611 10241 : bool flush_cleanup = false;
2612 10241 : gdk_return res = GDK_SUCCEED;
2613 :
2614 10241 : rotation_lock(lg);
2615 10241 : const lng current_file_size = LOG_DISABLED(lg) ? 0 : (lng) getfilepos(getFile(lg->current->output_log));
2616 :
2617 10241 : if (current_file_size == -1) {
2618 0 : rotation_unlock(lg);
2619 0 : return GDK_FAIL;
2620 : }
2621 : /* file size of 2 means only endian indicator present
2622 : * (i.e. effectively empty) */
2623 10241 : if (current_file_size <= 2) {
2624 6911 : rotation_unlock(lg);
2625 6911 : return GDK_SUCCEED;
2626 : }
2627 :
2628 3330 : if (!lg->flushnow &&
2629 3330 : !lg->current->next &&
2630 3330 : current_file_size > 2 &&
2631 3330 : (ATOMIC_GET(&lg->current->drops) > (ulng)lg->max_dropped ||
2632 3324 : current_file_size > lg->max_file_size ||
2633 3285 : (GDKusec() - lg->file_age) > lg->max_file_age) &&
2634 45 : (ulng) ATOMIC_GET(&lg->current->last_ts) > 0 &&
2635 45 : lg->saved_id + 1 == lg->id &&
2636 44 : ATOMIC_GET(&lg->current->refcount) == 1 /* no pending work on this file */ ) {
2637 40 : lg->id++;
2638 : /* start new file */
2639 40 : res = log_open_output(lg);
2640 40 : flush_cleanup = true;
2641 40 : do_rotate(lg);
2642 : }
2643 40 : if (flush_cleanup)
2644 40 : (void) do_flush_range_cleanup(lg);
2645 3330 : rotation_unlock(lg);
2646 3330 : return res;
2647 : }
2648 :
2649 : gdk_return
2650 7968 : log_flush(logger *lg, ulng ts)
2651 : {
2652 7968 : logged_range *pending = log_next_logfile(lg, ts);
2653 7968 : ulng lid = pending ? pending->id : 0, olid = lg->saved_id;
2654 7968 : if (LOG_DISABLED(lg)) {
2655 0 : lg->saved_id = lid;
2656 0 : lg->saved_tid = lg->tid;
2657 0 : if (lid)
2658 0 : log_cleanup_range(lg, lg->saved_id);
2659 0 : if (log_commit(lg, NULL, NULL, 0) != GDK_SUCCEED)
2660 0 : TRC_ERROR(GDK, "failed to commit");
2661 0 : return GDK_SUCCEED;
2662 : }
2663 7968 : if (lg->saved_id >= lid)
2664 : return GDK_SUCCEED;
2665 6688 : rotation_lock(lg);
2666 6688 : ulng lgid = lg->id;
2667 6688 : rotation_unlock(lg);
2668 6688 : if (lg->saved_id + 1 >= lgid) /* logger should first release the file */
2669 : return GDK_SUCCEED;
2670 6688 : log_return res = LOG_OK;
2671 6688 : ulng cid = olid;
2672 6688 : assert(lid <= lgid);
2673 : uint32_t *updated = NULL;
2674 : BUN nupdated = 0;
2675 : size_t allocated = 0;
2676 18929 : while (cid < lid && res == LOG_OK) {
2677 12241 : if (!lg->input_log) {
2678 12241 : char *filename;
2679 12241 : char id[32];
2680 12241 : if (snprintf(id, sizeof(id), LLFMT, cid + 1) >= (int) sizeof(id)) {
2681 0 : GDKfree(updated);
2682 0 : TRC_CRITICAL(GDK, "log_id filename is too large\n");
2683 0 : return GDK_FAIL;
2684 : }
2685 12241 : if ((filename = GDKfilepath(BBPselectfarm(PERSISTENT, 0, offheap), lg->dir, LOGFILE, id)) == NULL) {
2686 0 : GDKfree(updated);
2687 0 : return GDK_FAIL;
2688 : }
2689 12241 : if (strlen(filename) >= FILENAME_MAX) {
2690 0 : GDKfree(updated);
2691 0 : TRC_CRITICAL(GDK, "Logger filename path is too large\n");
2692 0 : GDKfree(filename);
2693 0 : return GDK_FAIL;
2694 : }
2695 :
2696 12241 : bool filemissing = false;
2697 12241 : if (log_open_input(lg, filename, &filemissing) != GDK_SUCCEED) {
2698 0 : GDKfree(updated);
2699 0 : GDKfree(filename);
2700 0 : return GDK_FAIL;
2701 : }
2702 12241 : GDKfree(filename);
2703 : }
2704 : /* we read the full file because skipping is impossible with current log format */
2705 12241 : log_lock(lg);
2706 12241 : if (updated == NULL) {
2707 6688 : nupdated = BATcount(lg->catalog_id);
2708 6688 : allocated = ((nupdated + 31) & ~31) / 8;
2709 6688 : if (allocated == 0)
2710 0 : allocated = 4;
2711 6688 : updated = GDKzalloc(allocated);
2712 6688 : if (updated == NULL) {
2713 0 : log_unlock(lg);
2714 0 : return GDK_FAIL;
2715 : }
2716 5553 : } else if (nupdated < BATcount(lg->catalog_id)) {
2717 109 : BUN n = BATcount(lg->catalog_id);
2718 109 : size_t a = ((n + 31) & ~31) / 8;
2719 109 : if (a > allocated) {
2720 25 : uint32_t *p = GDKrealloc(updated, a);
2721 25 : if (p == NULL) {
2722 0 : GDKfree(updated);
2723 0 : log_unlock(lg);
2724 0 : return GDK_FAIL;
2725 : }
2726 25 : updated = p;
2727 25 : memset(updated + allocated / 4, 0, a - allocated);
2728 25 : allocated = a;
2729 : }
2730 : nupdated = n;
2731 : }
2732 12241 : lg->flushing = true;
2733 12241 : res = log_read_transaction(lg, updated, nupdated);
2734 12241 : lg->flushing = false;
2735 12241 : log_unlock(lg);
2736 12241 : if (res == LOG_EOF) {
2737 12241 : log_close_input(lg);
2738 12241 : res = LOG_OK;
2739 : }
2740 12241 : cid++;
2741 : }
2742 6688 : if (lid > olid && res == LOG_OK) {
2743 6688 : rotation_lock(lg); /* protect against concurrent log_tflush rotate check */
2744 6688 : lg->saved_id = lid;
2745 6688 : rotation_unlock(lg);
2746 6688 : if (log_commit(lg, pending, updated, nupdated) != GDK_SUCCEED) {
2747 0 : TRC_ERROR(GDK, "failed to commit");
2748 0 : res = LOG_ERR;
2749 0 : rotation_lock(lg);
2750 0 : lg->saved_id = olid; /* reset !! */
2751 0 : rotation_unlock(lg);
2752 : }
2753 0 : if (res != LOG_ERR) {
2754 18929 : while (olid < lid) {
2755 : /* Try to cleanup, remove old log file, continue on failure! */
2756 12241 : olid++;
2757 12241 : (void) log_cleanup(lg, olid);
2758 : }
2759 : }
2760 6688 : if (res == LOG_OK)
2761 6688 : log_cleanup_range(lg, lg->saved_id);
2762 : }
2763 6688 : GDKfree(updated);
2764 6688 : return res == LOG_ERR ? GDK_FAIL : GDK_SUCCEED;
2765 : }
2766 :
2767 : /* Clean-up write-ahead log files already persisted in the BATs, leaving only the most recent one.
2768 : * Only the bak- files are deleted for the preserved WAL files.
2769 : */
2770 : lng
2771 28328 : log_changes(logger *lg)
2772 : {
2773 28328 : if (LOG_DISABLED(lg))
2774 : return 0;
2775 28328 : rotation_lock(lg);
2776 28328 : lng changes = lg->id - lg->saved_id - 1;
2777 28328 : rotation_unlock(lg);
2778 28328 : return changes;
2779 : }
2780 :
2781 : int
2782 430 : log_sequence(logger *lg, int seq, lng *id)
2783 : {
2784 430 : log_lock(lg);
2785 430 : BUN p = log_find(lg->seqs_id, lg->dseqs, seq);
2786 :
2787 430 : if (p != BUN_NONE) {
2788 315 : *id = *(lng *) Tloc(lg->seqs_val, p);
2789 :
2790 315 : log_unlock(lg);
2791 315 : return 1;
2792 : }
2793 115 : log_unlock(lg);
2794 115 : return 0;
2795 : }
2796 :
2797 : gdk_return
2798 185127 : log_constant(logger *lg, int type, const void *val, log_id id, lng offset, lng cnt)
2799 : {
2800 185127 : bte tpe = find_type(lg, type);
2801 185127 : gdk_return ok = GDK_SUCCEED;
2802 185127 : logformat l;
2803 185127 : lng nr;
2804 185127 : l.flag = LOG_UPDATE_CONST;
2805 185127 : l.id = id;
2806 185127 : nr = cnt;
2807 :
2808 185127 : if (LOG_DISABLED(lg) || !nr) {
2809 : /* logging is switched off */
2810 61382 : if (nr) {
2811 61382 : log_lock(lg);
2812 61382 : ok = la_bat_update_count(lg, id, offset + cnt, lg->tid);
2813 61382 : log_unlock(lg);
2814 : }
2815 61382 : return ok;
2816 : }
2817 :
2818 123745 : gdk_return(*wt) (const void *, stream *, size_t) = BATatoms[type].atomWrite;
2819 :
2820 123745 : assert(mnstr_errnr(lg->current->output_log) == MNSTR_NO__ERROR);
2821 247490 : if (mnstr_errnr(lg->current->output_log) != MNSTR_NO__ERROR ||
2822 247490 : log_write_format(lg, &l) != GDK_SUCCEED ||
2823 247490 : !mnstr_writeLng(lg->current->output_log, nr) ||
2824 247490 : mnstr_write(lg->current->output_log, &tpe, 1, 1) != 1 ||
2825 123745 : !mnstr_writeLng(lg->current->output_log, offset)) {
2826 0 : ATOMIC_DEC(&lg->current->refcount);
2827 0 : ok = GDK_FAIL;
2828 0 : goto bailout;
2829 : }
2830 :
2831 123745 : ok = wt(val, lg->current->output_log, 1);
2832 :
2833 123745 : TRC_DEBUG(WAL, "Logged %d " LLFMT " inserts\n", id, nr);
2834 :
2835 123745 : bailout:
2836 123745 : if (ok != GDK_SUCCEED) {
2837 0 : const char *err = mnstr_peek_error(lg->current->output_log);
2838 0 : TRC_CRITICAL(GDK, "write failed%s%s\n", err ? ": " : "", err ? err : "");
2839 : }
2840 : return ok;
2841 : }
2842 :
2843 : static gdk_return
2844 19576 : string_writer(logger *lg, BAT *b, lng offset, lng nr)
2845 : {
2846 19576 : size_t bufsz = lg->wbufsize, resize = 0;
2847 19576 : BUN end = (BUN) (offset + nr);
2848 19576 : char *buf = lg->wbuf;
2849 19576 : gdk_return res = GDK_SUCCEED;
2850 :
2851 19576 : if (!buf)
2852 : return GDK_FAIL;
2853 19576 : assert(mnstr_errnr(lg->current->output_log) == MNSTR_NO__ERROR);
2854 19576 : if (mnstr_errnr(lg->current->output_log) != MNSTR_NO__ERROR)
2855 : return GDK_FAIL;
2856 19576 : BATiter bi = bat_iterator(b);
2857 19576 : BUN p = (BUN) offset;
2858 39204 : for (; p < end;) {
2859 19628 : size_t sz = 0;
2860 19628 : if (resize) {
2861 2 : if ((buf = GDKrealloc(lg->wbuf, resize)) == NULL) {
2862 : res = GDK_FAIL;
2863 : break;
2864 : }
2865 2 : lg->wbuf = buf;
2866 2 : lg->wbufsize = bufsz = resize;
2867 2 : resize = 0;
2868 : }
2869 19628 : char *dst = buf;
2870 93907 : for (; p < end && sz < bufsz; p++) {
2871 74331 : const char *s = BUNtvar(bi, p);
2872 74331 : size_t len = strlen(s) + 1;
2873 74331 : if ((sz + len) > bufsz) {
2874 52 : if (len > bufsz)
2875 2 : resize = len + bufsz;
2876 : break;
2877 : } else {
2878 74279 : memcpy(dst, s, len);
2879 74279 : dst += len;
2880 74279 : sz += len;
2881 : }
2882 : }
2883 39254 : if (sz &&
2884 39252 : (!mnstr_writeLng(lg->current->output_log, (lng) sz) ||
2885 19626 : mnstr_write(lg->current->output_log, buf, sz, 1) != 1)) {
2886 : res = GDK_FAIL;
2887 : break;
2888 : }
2889 : }
2890 19576 : bat_iterator_end(&bi);
2891 19576 : return res;
2892 : }
2893 :
2894 : static gdk_return
2895 498520 : internal_log_bat(logger *lg, BAT *b, log_id id, lng offset, lng cnt, int sliced, lng total_cnt)
2896 : {
2897 498520 : bte tpe = find_type(lg, b->ttype);
2898 498520 : gdk_return ok = GDK_SUCCEED;
2899 498520 : logformat l;
2900 498520 : BUN p;
2901 498520 : lng nr;
2902 498520 : l.flag = LOG_UPDATE_BULK;
2903 498520 : l.id = id;
2904 498520 : nr = cnt;
2905 :
2906 498520 : if (LOG_DISABLED(lg) || !nr) {
2907 : /* logging is switched off */
2908 200247 : if (nr)
2909 145973 : return la_bat_update_count(lg, id, offset + cnt, lg->tid);
2910 : return GDK_SUCCEED;
2911 : }
2912 :
2913 268748 : gdk_return(*wt) (const void *, stream *, size_t) = BATatoms[b->ttype].atomWrite;
2914 :
2915 268748 : assert(mnstr_errnr(lg->current->output_log) == MNSTR_NO__ERROR);
2916 268748 : if (mnstr_errnr(lg->current->output_log) != MNSTR_NO__ERROR) {
2917 0 : ok = GDK_FAIL;
2918 0 : goto bailout;
2919 : }
2920 :
2921 268748 : if (lg->total_cnt == 0) /* signals single bulk message or first part of bat logged in parts */
2922 537188 : if (log_write_format(lg, &l) != GDK_SUCCEED ||
2923 665947 : !mnstr_writeLng(lg->current->output_log, total_cnt ? total_cnt : cnt) ||
2924 537188 : mnstr_write(lg->current->output_log, &tpe, 1, 1) != 1 ||
2925 408429 : !mnstr_writeLng(lg->current->output_log, total_cnt ? -1 : offset)) { /* offset = -1 indicates bat was logged in parts */
2926 0 : ok = GDK_FAIL;
2927 0 : goto bailout;
2928 : }
2929 268748 : if (!total_cnt)
2930 128759 : total_cnt = cnt;
2931 268748 : lg->total_cnt += cnt;
2932 :
2933 268748 : if (lg->total_cnt == total_cnt) /* This is the last to be logged part of this bat, we can already reset the total_cnt */
2934 268594 : lg->total_cnt = 0;
2935 :
2936 : /* if offset is just for the log, but BAT is already sliced, reset offset */
2937 268748 : if (sliced)
2938 1512 : offset = 0;
2939 268748 : if (b->ttype == TYPE_msk) {
2940 0 : BATiter bi = bat_iterator(b);
2941 0 : if (offset % 32 == 0) {
2942 0 : if (!mnstr_writeIntArray(lg->current->output_log, (int *) ((char *) bi.base + offset / 32),
2943 0 : (size_t) ((nr + 31) / 32)))
2944 0 : ok = GDK_FAIL;
2945 : } else {
2946 0 : for (lng i = 0; i < nr; i += 32) {
2947 : uint32_t v = 0;
2948 0 : for (int j = 0; j < 32 && i + j < nr; j++)
2949 0 : v |= (uint32_t) Tmskval(&bi, (BUN) (offset + i + j)) << j;
2950 0 : if (!mnstr_writeInt(lg->current->output_log, (int) v)) {
2951 : ok = GDK_FAIL;
2952 : break;
2953 : }
2954 : }
2955 : }
2956 0 : bat_iterator_end(&bi);
2957 517284 : } else if (b->ttype < TYPE_str && !isVIEW(b)) {
2958 248536 : BATiter bi = bat_iterator(b);
2959 248536 : const void *t = BUNtail(bi, (BUN) offset);
2960 :
2961 248536 : ok = wt(t, lg->current->output_log, (size_t) nr);
2962 248536 : bat_iterator_end(&bi);
2963 20212 : } else if (b->ttype == TYPE_str) {
2964 : /* efficient string writes */
2965 19570 : ok = string_writer(lg, b, offset, nr);
2966 : } else {
2967 642 : BATiter bi = bat_iterator(b);
2968 642 : BUN end = (BUN) (offset + nr);
2969 1642 : for (p = (BUN) offset; p < end && ok == GDK_SUCCEED; p++) {
2970 1000 : const void *t = BUNtail(bi, p);
2971 :
2972 1000 : ok = wt(t, lg->current->output_log, 1);
2973 : }
2974 642 : bat_iterator_end(&bi);
2975 : }
2976 :
2977 268748 : TRC_DEBUG(WAL, "Logged %d " LLFMT " inserts\n", id, nr);
2978 :
2979 268748 : bailout:
2980 268748 : if (ok != GDK_SUCCEED) {
2981 0 : ATOMIC_DEC(&lg->current->refcount);
2982 0 : const char *err = mnstr_peek_error(lg->current->output_log);
2983 0 : TRC_CRITICAL(GDK, "write failed%s%s\n", err ? ": " : "", err ? err : "");
2984 : }
2985 : return ok;
2986 : }
2987 :
2988 : /*
2989 : * Changes made to the BAT descriptor should be stored in the log
2990 : * files. Actually, we need to save the descriptor file, perhaps we
2991 : * should simply introduce a versioning scheme.
2992 : */
2993 : gdk_return
2994 236416 : log_bat_persists(logger *lg, BAT *b, log_id id)
2995 : {
2996 236416 : log_lock(lg);
2997 236416 : bte ta = find_type(lg, b->ttype);
2998 236416 : logformat l;
2999 :
3000 236416 : if (log_add_bat(lg, b, id, -1) != GDK_SUCCEED) {
3001 0 : log_unlock(lg);
3002 0 : if (!LOG_DISABLED(lg))
3003 0 : ATOMIC_DEC(&lg->current->refcount);
3004 0 : return GDK_FAIL;
3005 : }
3006 :
3007 236416 : l.flag = LOG_CREATE;
3008 236416 : l.id = id;
3009 236416 : if (!LOG_DISABLED(lg)) {
3010 156760 : assert(mnstr_errnr(lg->current->output_log) == MNSTR_NO__ERROR);
3011 313520 : if (mnstr_errnr(lg->current->output_log) != MNSTR_NO__ERROR ||
3012 313520 : log_write_format(lg, &l) != GDK_SUCCEED ||
3013 156760 : mnstr_write(lg->current->output_log, &ta, 1, 1) != 1) {
3014 0 : log_unlock(lg);
3015 0 : ATOMIC_DEC(&lg->current->refcount);
3016 0 : return GDK_FAIL;
3017 : }
3018 : }
3019 236416 : TRC_DEBUG(WAL, "id (%d) bat (%d)\n", id, b->batCacheid);
3020 236416 : gdk_return r = internal_log_bat(lg, b, id, 0, BATcount(b), 0, 0);
3021 236416 : log_unlock(lg);
3022 236416 : if (r != GDK_SUCCEED)
3023 0 : ATOMIC_DEC(&lg->current->refcount);
3024 : return r;
3025 : }
3026 :
3027 : gdk_return
3028 22092 : log_bat_transient(logger *lg, log_id id)
3029 : {
3030 22092 : log_lock(lg);
3031 22092 : log_bid bid = internal_find_bat(lg, id, -1);
3032 22092 : logformat l;
3033 :
3034 22092 : if (bid < 0) {
3035 0 : log_unlock(lg);
3036 0 : return GDK_FAIL;
3037 : }
3038 22092 : if (!bid) {
3039 0 : GDKerror("log_bat_transient failed to find bid for object %d\n", id);
3040 0 : log_unlock(lg);
3041 0 : return GDK_FAIL;
3042 : }
3043 22092 : l.flag = LOG_DESTROY;
3044 22092 : l.id = id;
3045 :
3046 22092 : if (!LOG_DISABLED(lg)) {
3047 9637 : if (log_write_format(lg, &l) != GDK_SUCCEED) {
3048 0 : TRC_CRITICAL(GDK, "write failed\n");
3049 0 : log_unlock(lg);
3050 0 : ATOMIC_DEC(&lg->current->refcount);
3051 0 : return GDK_FAIL;
3052 : }
3053 : }
3054 22092 : TRC_DEBUG(WAL, "Logged destroyed bat (%d) %d\n", id, bid);
3055 22092 : BAT *b = BBPquickdesc(bid);
3056 22092 : assert(b);
3057 22092 : BUN cnt = BATcount(b);
3058 22092 : ATOMIC_ADD(&lg->current->drops, cnt);
3059 22092 : gdk_return r = log_del_bat(lg, bid);
3060 22092 : log_unlock(lg);
3061 22092 : if (r != GDK_SUCCEED)
3062 0 : ATOMIC_DEC(&lg->current->refcount);
3063 : return r;
3064 : }
3065 :
3066 : static gdk_return
3067 116572 : log_bat_group(logger *lg, log_id id)
3068 : {
3069 116572 : if (LOG_DISABLED(lg))
3070 : return GDK_SUCCEED;
3071 :
3072 76042 : logformat l;
3073 76042 : l.flag = LOG_BAT_GROUP;
3074 76042 : l.id = id;
3075 76042 : gdk_return r = log_write_format(lg, &l);
3076 76042 : return r;
3077 : }
3078 :
3079 : gdk_return
3080 58286 : log_bat_group_start(logger *lg, log_id id)
3081 : {
3082 : /*positive table id represent start of logged table */
3083 58286 : return log_bat_group(lg, id);
3084 : }
3085 :
3086 : gdk_return
3087 58286 : log_bat_group_end(logger *lg, log_id id)
3088 : {
3089 : /*negative table id represent end of logged table */
3090 58286 : return log_bat_group(lg, -id);
3091 : }
3092 :
3093 : gdk_return
3094 259393 : log_bat(logger *lg, BAT *b, log_id id, lng offset, lng cnt, lng total_cnt)
3095 : {
3096 259393 : log_lock(lg);
3097 259393 : gdk_return r = internal_log_bat(lg, b, id, offset, cnt, 0, total_cnt);
3098 259393 : log_unlock(lg);
3099 259393 : return r;
3100 : }
3101 :
3102 : gdk_return
3103 2747 : log_delta(logger *lg, BAT *uid, BAT *uval, log_id id)
3104 : {
3105 2747 : log_lock(lg);
3106 2747 : bte tpe = find_type(lg, uval->ttype);
3107 2747 : gdk_return ok = GDK_SUCCEED;
3108 2747 : logformat l;
3109 2747 : BUN p;
3110 2747 : lng nr;
3111 :
3112 2747 : if (BATtdense(uid)) {
3113 2711 : ok = internal_log_bat(lg, uval, id, uid->tseqbase, BATcount(uval), 1, 0);
3114 2711 : log_unlock(lg);
3115 2711 : if (!LOG_DISABLED(lg) && ok != GDK_SUCCEED)
3116 0 : ATOMIC_DEC(&lg->current->refcount);
3117 2711 : return ok;
3118 : }
3119 :
3120 36 : assert(uid->ttype == TYPE_oid || uid->ttype == TYPE_void);
3121 :
3122 36 : l.flag = LOG_UPDATE;
3123 36 : l.id = id;
3124 36 : nr = (BATcount(uval));
3125 36 : assert(nr);
3126 :
3127 36 : if (LOG_DISABLED(lg)) {
3128 : /* logging is switched off */
3129 17 : log_unlock(lg);
3130 17 : return GDK_SUCCEED;
3131 : }
3132 :
3133 19 : BATiter vi = bat_iterator(uval);
3134 19 : gdk_return(*wh) (const void *, stream *, size_t) = BATatoms[TYPE_oid].atomWrite;
3135 19 : gdk_return(*wt) (const void *, stream *, size_t) = BATatoms[uval->ttype].atomWrite;
3136 :
3137 19 : assert(mnstr_errnr(lg->current->output_log) == MNSTR_NO__ERROR);
3138 38 : if (mnstr_errnr(lg->current->output_log) != MNSTR_NO__ERROR ||
3139 38 : log_write_format(lg, &l) != GDK_SUCCEED ||
3140 38 : !mnstr_writeLng(lg->current->output_log, nr) ||
3141 19 : mnstr_write(lg->current->output_log, &tpe, 1, 1) != 1) {
3142 0 : ok = GDK_FAIL;
3143 0 : goto bailout;
3144 : }
3145 1074 : for (p = 0; p < BATcount(uid) && ok == GDK_SUCCEED; p++) {
3146 1055 : const oid id = BUNtoid(uid, p);
3147 :
3148 1055 : ok = wh(&id, lg->current->output_log, 1);
3149 : }
3150 19 : if (uval->ttype == TYPE_msk) {
3151 0 : if (!mnstr_writeIntArray(lg->current->output_log, vi.base,
3152 0 : (BATcount(uval) + 31) / 32))
3153 0 : ok = GDK_FAIL;
3154 32 : } else if (uval->ttype < TYPE_str && !isVIEW(uval)) {
3155 13 : const void *t = BUNtail(vi, 0);
3156 :
3157 13 : ok = wt(t, lg->current->output_log, (size_t) nr);
3158 6 : } else if (uval->ttype == TYPE_str) {
3159 : /* efficient string writes */
3160 6 : ok = string_writer(lg, uval, 0, nr);
3161 : } else {
3162 0 : for (p = 0; p < BATcount(uid) && ok == GDK_SUCCEED; p++) {
3163 0 : const void *val = BUNtail(vi, p);
3164 :
3165 0 : ok = wt(val, lg->current->output_log, 1);
3166 : }
3167 : }
3168 :
3169 19 : TRC_DEBUG(WAL, "Logged %d " LLFMT " inserts\n", id, nr);
3170 :
3171 19 : bailout:
3172 19 : bat_iterator_end(&vi);
3173 19 : if (ok != GDK_SUCCEED) {
3174 0 : const char *err = mnstr_peek_error(lg->current->output_log);
3175 0 : TRC_CRITICAL(GDK, "write failed%s%s\n", err ? ": " : "", err ? err : "");
3176 0 : ATOMIC_DEC(&lg->current->refcount);
3177 : }
3178 19 : log_unlock(lg);
3179 19 : return ok;
3180 : }
3181 :
3182 : static inline bool
3183 56721 : check_rotation_conditions(logger *lg)
3184 : {
3185 56721 : if (LOG_DISABLED(lg))
3186 : return false;
3187 :
3188 56718 : if (lg->current->next)
3189 : return false; /* do not rotate if there is already a prepared next current */
3190 56718 : if (mnstr_errnr(lg->current->output_log) != MNSTR_NO__ERROR)
3191 : return true;
3192 56718 : const lng current_file_size = (lng) getfilepos(getFile(lg->current->output_log));
3193 :
3194 56718 : if (current_file_size == -1)
3195 : return false;
3196 :
3197 56718 : assert(current_file_size >= 0);
3198 :
3199 56718 : if (current_file_size == 2)
3200 : return false;
3201 :
3202 2802 : bool res = (lg->saved_id + 1 >= lg->id && ATOMIC_GET(&lg->current->drops) > (ulng)lg->max_dropped) ||
3203 57142 : current_file_size > lg->max_file_size ||
3204 49877 : (GDKusec() - lg->file_age) > lg->max_file_age;
3205 :
3206 54346 : return res;
3207 : }
3208 :
3209 : gdk_return
3210 62355 : log_tend(logger *lg)
3211 : {
3212 62355 : TRC_DEBUG(WAL, "tend %d\n", lg->tid);
3213 :
3214 62355 : if (LOG_DISABLED(lg))
3215 : return GDK_SUCCEED;
3216 :
3217 56718 : gdk_return result;
3218 56718 : logformat l;
3219 56718 : l.flag = LOG_END;
3220 56718 : l.id = lg->tid;
3221 :
3222 56718 : if ((result = log_write_format(lg, &l)) == GDK_SUCCEED)
3223 56718 : ATOMIC_INC(&lg->nr_flushers);
3224 : return result;
3225 : }
3226 :
3227 : #define flush_lock(lg) MT_lock_set(&(lg)->flush_lock)
3228 : #define flush_unlock(lg) MT_lock_unset(&(lg)->flush_lock)
3229 :
3230 : static inline gdk_return
3231 55951 : do_flush(logged_range *range)
3232 : {
3233 : /* assumes flush lock */
3234 55951 : stream *output_log = range->output_log;
3235 55951 : ulng ts = ATOMIC_GET(&range->last_ts);
3236 :
3237 55951 : if (mnstr_flush(output_log, MNSTR_FLUSH_DATA) ||
3238 55951 : (!(ATOMIC_GET(&GDKdebug) & NOSYNCMASK) && mnstr_fsync(output_log)))
3239 0 : return GDK_FAIL;
3240 55951 : ATOMIC_SET(&range->flushed_ts, ts);
3241 55951 : return GDK_SUCCEED;
3242 : }
3243 :
3244 : static inline void
3245 62352 : log_tdone(logger *lg, logged_range *range, ulng commit_ts)
3246 : {
3247 62352 : (void) lg;
3248 62352 : TRC_DEBUG(WAL, "tdone " LLFMT "\n", commit_ts);
3249 :
3250 62352 : if ((ulng) ATOMIC_GET(&range->last_ts) < commit_ts)
3251 61585 : ATOMIC_SET(&range->last_ts, commit_ts);
3252 62352 : }
3253 :
3254 : gdk_return
3255 62355 : log_tflush(logger *lg, ulng file_id, ulng commit_ts)
3256 : {
3257 62355 : rotation_lock(lg);
3258 62355 : if (lg->flushnow) {
3259 5634 : logged_range *p = lg->current;
3260 5634 : assert(lg->flush_ranges == lg->current);
3261 5634 : assert(ATOMIC_GET(&lg->current->flushed_ts) == ATOMIC_GET(&lg->current->last_ts));
3262 5634 : log_tdone(lg, lg->current, commit_ts);
3263 5634 : ATOMIC_SET(&lg->current->flushed_ts, commit_ts);
3264 5634 : lg->id++;
3265 5634 : lg->flushnow = false;
3266 5634 : if (log_open_output(lg) != GDK_SUCCEED)
3267 0 : GDKfatal("Could not create new log file\n"); /* TODO: does not have to be fatal (yet) */
3268 5634 : do_rotate(lg);
3269 5634 : (void) do_flush_range_cleanup(lg);
3270 5634 : assert(lg->flush_ranges == lg->current);
3271 5634 : rotation_unlock(lg);
3272 5634 : return log_commit(lg, p, NULL, 0);
3273 : }
3274 :
3275 56721 : if (LOG_DISABLED(lg)) {
3276 3 : rotation_unlock(lg);
3277 3 : return GDK_SUCCEED;
3278 : }
3279 :
3280 56718 : logged_range *frange = do_flush_range_cleanup(lg);
3281 :
3282 56963 : while (frange->next && frange->id < file_id) {
3283 : assert(frange->next);
3284 : frange = frange->next;
3285 : }
3286 :
3287 56718 : log_tdone(lg, frange, commit_ts);
3288 :
3289 56718 : if ((ulng) ATOMIC_GET(&frange->flushed_ts) < commit_ts) {
3290 : /* delay needed ? */
3291 :
3292 55951 : flush_lock(lg);
3293 : /* check it one more time */
3294 55951 : if ((ulng) ATOMIC_GET(&frange->flushed_ts) < commit_ts)
3295 55951 : do_flush(frange);
3296 55951 : flush_unlock(lg);
3297 : }
3298 : /* else somebody else has flushed our log file */
3299 :
3300 56718 : if (ATOMIC_DEC(&frange->refcount) == 1 && !LOG_DISABLED(lg)) {
3301 54749 : if (frange != lg->current && frange->output_log) {
3302 193 : close_stream(frange->output_log);
3303 193 : frange->output_log = NULL;
3304 : }
3305 : }
3306 :
3307 56718 : if (ATOMIC_DEC(&lg->nr_flushers) == 0) {
3308 : /* I am the last flusher
3309 : * if present,
3310 : * wake up the exclusive flusher in log_tstart */
3311 : /* rotation_lock is still being held */
3312 55084 : MT_cond_signal(&lg->excl_flush_cv);
3313 : }
3314 56718 : rotation_unlock(lg);
3315 :
3316 56718 : return GDK_SUCCEED;
3317 : }
3318 :
3319 : static gdk_return
3320 6879 : log_tsequence_(logger *lg, int seq, lng val)
3321 : {
3322 6879 : logformat l;
3323 :
3324 6879 : if (LOG_DISABLED(lg))
3325 : return GDK_SUCCEED;
3326 2827 : l.flag = LOG_SEQ;
3327 2827 : l.id = seq;
3328 :
3329 2827 : TRC_DEBUG(WAL, "tsequence(%d," LLFMT ")\n", seq, val);
3330 :
3331 2827 : assert(mnstr_errnr(lg->current->output_log) == MNSTR_NO__ERROR);
3332 5654 : if (mnstr_errnr(lg->current->output_log) != MNSTR_NO__ERROR ||
3333 5654 : log_write_format(lg, &l) != GDK_SUCCEED ||
3334 2827 : !mnstr_writeLng(lg->current->output_log, val)) {
3335 0 : TRC_CRITICAL(GDK, "write failed\n");
3336 0 : ATOMIC_DEC(&lg->current->refcount);
3337 0 : return GDK_FAIL;
3338 : }
3339 : return GDK_SUCCEED;
3340 : }
3341 :
3342 : /* a transaction in it self */
3343 : gdk_return
3344 6879 : log_tsequence(logger *lg, int seq, lng val)
3345 : {
3346 6879 : BUN p;
3347 :
3348 6879 : TRC_DEBUG(WAL, "tsequence(%d," LLFMT ")\n", seq, val);
3349 :
3350 6879 : log_lock(lg);
3351 6879 : MT_lock_set(&lg->seqs_id->theaplock);
3352 6879 : BUN inserted = lg->seqs_id->batInserted;
3353 6879 : MT_lock_unset(&lg->seqs_id->theaplock);
3354 6879 : if ((p = log_find(lg->seqs_id, lg->dseqs, seq)) != BUN_NONE && p >= inserted) {
3355 1619 : assert(lg->seqs_val->hseqbase == 0);
3356 1619 : if (BUNreplace(lg->seqs_val, p, &val, true) != GDK_SUCCEED) {
3357 0 : log_unlock(lg);
3358 0 : return GDK_FAIL;
3359 : }
3360 : } else {
3361 4898 : if (p != BUN_NONE) {
3362 4898 : oid pos = p;
3363 4898 : if (BUNappend(lg->dseqs, &pos, true) != GDK_SUCCEED) {
3364 0 : log_unlock(lg);
3365 0 : return GDK_FAIL;
3366 : }
3367 : }
3368 10520 : if (BUNappend(lg->seqs_id, &seq, true) != GDK_SUCCEED ||
3369 5260 : BUNappend(lg->seqs_val, &val, true) != GDK_SUCCEED) {
3370 0 : log_unlock(lg);
3371 0 : return GDK_FAIL;
3372 : }
3373 : }
3374 6879 : gdk_return r = log_tsequence_(lg, seq, val);
3375 6879 : log_unlock(lg);
3376 6879 : return r;
3377 : }
3378 :
3379 : static gdk_return
3380 12638 : bm_commit(logger *lg, logged_range *pending, uint32_t *updated, BUN maxupdated)
3381 : {
3382 12638 : log_lock(lg);
3383 12638 : BAT *b = lg->catalog_bid;
3384 12638 : const log_bid *bids;
3385 :
3386 12638 : bids = (log_bid *) Tloc(b, 0);
3387 249015 : for (BUN p = b->batInserted, cnt = pending ? pending->cnt : BATcount(b); p < cnt; p++) {
3388 236377 : log_bid bid = bids[p];
3389 236377 : BAT *lb = BBP_desc(bid);
3390 :
3391 236377 : assert(bid);
3392 236377 : if (lb->batCacheid == 0 || BATmode(lb, false) != GDK_SUCCEED) {
3393 0 : GDKwarning("Failed to set bat (%d%s) persistent\n", bid, !lb ? " gone" : "");
3394 0 : log_unlock(lg);
3395 0 : return GDK_FAIL;
3396 : }
3397 :
3398 236377 : assert(lb->batRestricted != BAT_WRITE);
3399 :
3400 236377 : TRC_DEBUG(WAL, "create %d (%d)\n", bid, BBP_lrefs(bid));
3401 : }
3402 : /* bm_subcommit releases the lock */
3403 12638 : return bm_subcommit(lg, pending, updated, maxupdated);
3404 : }
3405 :
3406 : static gdk_return
3407 236670 : log_add_bat(logger *lg, BAT *b, log_id id, int tid)
3408 : {
3409 236670 : log_bid bid = internal_find_bat(lg, id, tid);
3410 236670 : lng cnt = 0;
3411 236670 : lng lid = lng_nil;
3412 :
3413 236670 : assert(b->batRestricted != BAT_WRITE);
3414 236670 : assert(b->batRole == PERSISTENT);
3415 236670 : if (bid < 0)
3416 : return GDK_FAIL;
3417 236670 : if (bid) {
3418 155567 : if (bid != b->batCacheid) {
3419 155564 : if (log_del_bat(lg, bid) != GDK_SUCCEED)
3420 : return GDK_FAIL;
3421 : } else {
3422 : return GDK_SUCCEED;
3423 : }
3424 : }
3425 236667 : bid = b->batCacheid;
3426 236667 : TRC_DEBUG(WAL, "create %d\n", id);
3427 236667 : assert(log_find(lg->catalog_bid, lg->dcatalog, bid) == BUN_NONE);
3428 473334 : if (BUNappend(lg->catalog_bid, &bid, true) != GDK_SUCCEED ||
3429 473334 : BUNappend(lg->catalog_id, &id, true) != GDK_SUCCEED ||
3430 473334 : BUNappend(lg->catalog_cnt, &cnt, false) != GDK_SUCCEED ||
3431 236667 : BUNappend(lg->catalog_lid, &lid, false) != GDK_SUCCEED)
3432 0 : return GDK_FAIL;
3433 236667 : if (lg->current)
3434 236413 : lg->current->cnt++;
3435 236667 : BBPretain(bid);
3436 236667 : return GDK_SUCCEED;
3437 : }
3438 :
3439 : static gdk_return
3440 177696 : log_del_bat(logger *lg, log_bid bid)
3441 : {
3442 177696 : BUN p = log_find(lg->catalog_bid, lg->dcatalog, bid);
3443 177696 : lng lid = lg->tid;
3444 :
3445 177696 : assert(p != BUN_NONE);
3446 177696 : if (p == BUN_NONE) {
3447 : GDKerror("cannot find BAT\n");
3448 : return GDK_FAIL;
3449 : }
3450 :
3451 177696 : assert(lg->catalog_lid->hseqbase == 0);
3452 177696 : return BUNreplace(lg->catalog_lid, p, &lid, false);
3453 : }
3454 :
3455 : /* returns -1 on failure, 0 when not found, > 0 when found */
3456 : log_bid
3457 23213 : log_find_bat(logger *lg, log_id id)
3458 : {
3459 23213 : log_lock(lg);
3460 23213 : log_bid bid = internal_find_bat(lg, id, -1);
3461 23213 : log_unlock(lg);
3462 23213 : if (!bid) {
3463 0 : GDKerror("logger_find_bat failed to find bid for object %d\n", id);
3464 0 : return GDK_FAIL;
3465 : }
3466 : return bid;
3467 : }
3468 :
3469 :
3470 :
3471 : gdk_return
3472 62356 : log_tstart(logger *lg, bool flushnow, ulng *file_id)
3473 : {
3474 62356 : rotation_lock(lg);
3475 62356 : if (flushnow) {
3476 5635 : if (file_id == NULL) {
3477 : /* special case: ask store_manager to rotate log file */
3478 1 : lg->file_age = 0;
3479 1 : rotation_unlock(lg);
3480 1 : return GDK_SUCCEED;
3481 : }
3482 : /* I am now the exclusive flusher */
3483 5634 : while (ATOMIC_GET(&lg->nr_flushers)) {
3484 : /* I am waiting until all existing flushers are done */
3485 0 : MT_cond_wait(&lg->excl_flush_cv, &lg->rotation_lock);
3486 : }
3487 5634 : assert(ATOMIC_GET(&lg->nr_flushers) == 0);
3488 :
3489 5634 : if (ATOMIC_GET(&lg->current->last_ts)) {
3490 2190 : lg->id++;
3491 2190 : if (log_open_output(lg) != GDK_SUCCEED)
3492 0 : GDKfatal("Could not create new log file\n"); /* TODO: does not have to be fatal (yet) */
3493 : }
3494 5634 : do_rotate(lg);
3495 5634 : (void) do_flush_range_cleanup(lg);
3496 5634 : rotation_unlock(lg);
3497 :
3498 5634 : if (lg->saved_id + 1 < lg->id)
3499 5169 : log_flush(lg, (1ULL << 63));
3500 5634 : lg->flushnow = flushnow;
3501 : } else {
3502 56721 : if (check_rotation_conditions(lg)) {
3503 4470 : lg->id++;
3504 4470 : if (log_open_output(lg) != GDK_SUCCEED)
3505 0 : GDKfatal("Could not create new log file\n"); /* TODO: does not have to be fatal (yet) */
3506 : }
3507 56721 : do_rotate(lg);
3508 56721 : rotation_unlock(lg);
3509 : }
3510 :
3511 62355 : if (LOG_DISABLED(lg))
3512 : return GDK_SUCCEED;
3513 :
3514 56718 : ATOMIC_INC(&lg->current->refcount);
3515 56718 : *file_id = lg->current->id;
3516 56718 : logformat l;
3517 56718 : l.flag = LOG_START;
3518 56718 : l.id = ++lg->tid;
3519 :
3520 56718 : TRC_DEBUG(WAL, "tstart %d\n", lg->tid);
3521 56718 : if (log_write_format(lg, &l) != GDK_SUCCEED) {
3522 0 : ATOMIC_DEC(&lg->current->refcount);
3523 0 : return GDK_FAIL;
3524 : }
3525 :
3526 : return GDK_SUCCEED;
3527 : }
3528 :
3529 : void
3530 116 : log_printinfo(logger *lg)
3531 : {
3532 116 : if (!rotation_trylock(lg, 1000)) {
3533 0 : printf("Logger is currently locked, so no logger information\n");
3534 0 : return;
3535 : }
3536 116 : printf("logger %s:\n", lg->fn);
3537 116 : printf("current log file "ULLFMT", last handled log file "ULLFMT"\n",
3538 : lg->id, lg->saved_id);
3539 116 : printf("current transaction id %d, saved transaction id %d\n",
3540 : lg->tid, lg->saved_tid);
3541 116 : printf("number of flushers: %d\n", (int) ATOMIC_GET(&lg->nr_flushers));
3542 116 : printf("number of catalog entries "BUNFMT", of which "BUNFMT" deleted\n",
3543 116 : lg->catalog_bid->batCount, lg->dcatalog->batCount);
3544 294 : for (logged_range *p = lg->pending; p; p = p->next) {
3545 178 : char buf[32];
3546 178 : if ((lg->debug & 128 || lg->inmemory) ||
3547 178 : p->output_log == NULL ||
3548 116 : snprintf(buf, sizeof(buf), ", file size %"PRIu64, (uint64_t) getfilepos(getFile(lg->current->output_log))) >= (int) sizeof(buf))
3549 62 : buf[0] = 0;
3550 240 : printf("pending range "ULLFMT": drops %"PRIu64", last_ts %"PRIu64", flushed_ts %"PRIu64", refcount %"PRIu64"%s%s\n", p->id, (uint64_t) ATOMIC_GET(&p->drops), (uint64_t) ATOMIC_GET(&p->last_ts), (uint64_t) ATOMIC_GET(&p->flushed_ts), (uint64_t) ATOMIC_GET(&p->refcount), buf, p == lg->current ? " (current)" : "");
3551 : }
3552 116 : rotation_unlock(lg);
3553 : }
|
