Brunobkr/llama.cpp_AlgMor24_github

1#include "common.h"2#include "log.h"3 4#include <chrono>5#include <condition_variable>6#include <cstdarg>7#include <cstdio>8#include <cstdlib>9#include <cstring>10#include <mutex>11#include <sstream>12#include <thread>13#include <vector>14#include <algorithm>15 16#if defined(_WIN32)17#    define WIN32_LEAN_AND_MEAN18#    ifndef NOMINMAX19#       define NOMINMAX20#    endif21#    include <io.h>22#    include <windows.h>23#    define isatty _isatty24#    define fileno _fileno25#else26#    include <unistd.h>27#endif // defined(_WIN32)28 29int common_log_verbosity_thold = LOG_DEFAULT_LLAMA;30 31int common_log_get_verbosity_thold(void) {32    return common_log_verbosity_thold;33}34 35void common_log_set_verbosity_thold(int verbosity) {36    common_log_verbosity_thold = verbosity;37}38 39static int64_t t_us() {40    return std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::system_clock::now().time_since_epoch()).count();41}42 43// colors44enum common_log_col : int {45    COMMON_LOG_COL_DEFAULT = 0,46    COMMON_LOG_COL_BOLD,47    COMMON_LOG_COL_RED,48    COMMON_LOG_COL_GREEN,49    COMMON_LOG_COL_YELLOW,50    COMMON_LOG_COL_BLUE,51    COMMON_LOG_COL_MAGENTA,52    COMMON_LOG_COL_CYAN,53    COMMON_LOG_COL_WHITE,54};55 56// disable colors by default57static const char* g_col[] = {58    "",59    "",60    "",61    "",62    "",63    "",64    "",65    "",66    "",67};68 69struct common_log_entry {70    enum ggml_log_level level {GGML_LOG_LEVEL_INFO};71 72    std::vector<char> msg;73 74    int64_t timestamp { 0 };75    bool is_end       { false }; // signals the worker thread to stop76    bool prefix       { false };77 78    common_log_entry(size_t size = 256) : msg(size) { }79 80    void print(FILE * file = nullptr) const {81        FILE * fcur = file;82        if (!fcur) {83            // stderr displays DBG messages only when their verbosity level is not higher than the threshold84            // these messages will still be logged to a file85            if (level == GGML_LOG_LEVEL_DEBUG && common_log_verbosity_thold < LOG_DEFAULT_DEBUG) {86                return;87            }88 89            fcur = stdout;90 91            if (level != GGML_LOG_LEVEL_NONE) {92                fcur = stderr;93            }94        }95 96        if (level != GGML_LOG_LEVEL_NONE && level != GGML_LOG_LEVEL_CONT && prefix) {97            if (timestamp) {98                // [M.s.ms.us]99                fprintf(fcur, "%s%d.%02d.%03d.%03d%s ",100                        g_col[COMMON_LOG_COL_BLUE],101                        (int) (timestamp / 1000000 / 60),102                        (int) (timestamp / 1000000 % 60),103                        (int) (timestamp / 1000 % 1000),104                        (int) (timestamp % 1000),105                        g_col[COMMON_LOG_COL_DEFAULT]);106            }107 108            switch (level) {109                case GGML_LOG_LEVEL_INFO:  fprintf(fcur, "%sI %s", g_col[COMMON_LOG_COL_GREEN],   g_col[COMMON_LOG_COL_DEFAULT]); break;110                case GGML_LOG_LEVEL_WARN:  fprintf(fcur, "%sW %s", g_col[COMMON_LOG_COL_MAGENTA], ""                        ); break;111                case GGML_LOG_LEVEL_ERROR: fprintf(fcur, "%sE %s", g_col[COMMON_LOG_COL_RED],     ""                        ); break;112                case GGML_LOG_LEVEL_DEBUG: fprintf(fcur, "%sD %s", g_col[COMMON_LOG_COL_YELLOW],  ""                        ); break;113                default:114                    break;115            }116        }117 118        fprintf(fcur, "%s", msg.data());119 120        if (level == GGML_LOG_LEVEL_WARN || level == GGML_LOG_LEVEL_ERROR || level == GGML_LOG_LEVEL_DEBUG) {121            fprintf(fcur, "%s", g_col[COMMON_LOG_COL_DEFAULT]);122        }123 124        fflush(fcur);125    }126};127 128struct common_log {129    // default capacity130    common_log(size_t capacity = 512) {131        file       = nullptr;132        prefix     = false;133        timestamps = false;134        running    = false;135        t_start    = t_us();136 137        queue.resize(capacity, common_log_entry(256));138        head = 0;139        tail = 0;140 141        resume();142    }143 144    ~common_log() {145        pause();146        if (file) {147            fclose(file);148        }149    }150 151private:152    std::mutex              mtx;153    std::thread             thrd;154    std::condition_variable cv_new;  // new entry155    std::condition_variable cv_full; // wait on full156 157    FILE * file;158 159    bool prefix;160    bool timestamps;161    bool running;162 163    int64_t t_start;164 165    // queue of entries166    std::vector<common_log_entry> queue;167    size_t head;168    size_t tail;169 170    bool print_entry(const common_log_entry & e) const {171        if (e.is_end) return true;172 173        e.print();174        if (file) {175            e.print(file);176        }177        return false;178    }179 180    bool flush_queue(size_t start_head, size_t end_tail, size_t & out_head) const {181        bool stop = false;182        size_t h = start_head;183        while (h != end_tail && !stop) {184            stop = print_entry(queue[h]);185            h = (h + 1) % queue.size();186        }187        out_head = h;188        return stop;189    }190 191public:192    bool is_full() const {193        return ((tail + 1) % queue.size()) == head;194    }195 196    bool is_empty() const {197        return head == tail;198    }199 200    void add(enum ggml_log_level level, const char * fmt, va_list args) {201        std::unique_lock<std::mutex> lock(mtx);202 203        // block if the queue is full204        cv_full.wait(lock, [this]() { return !running || !is_full(); });205 206        if (!running) {207            // discard messages while the worker thread is paused208            return;209        }210 211        auto & entry = queue[tail];212 213        {214            // cannot use args twice, so make a copy in case we need to expand the buffer215            va_list args_copy;216            va_copy(args_copy, args);217 218#if 1219            const size_t n = vsnprintf(entry.msg.data(), entry.msg.size(), fmt, args);220            if (n >= entry.msg.size()) {221                entry.msg.resize(n + 1);222                vsnprintf(entry.msg.data(), entry.msg.size(), fmt, args_copy);223            }224#else225            // hack for bolding arguments226 227            std::stringstream ss;228            for (int i = 0; fmt[i] != 0; i++) {229                if (fmt[i] == '%') {230                    ss << LOG_COL_BOLD;231                    while (fmt[i] != ' ' && fmt[i] != ')' && fmt[i] != ']' && fmt[i] != 0) ss << fmt[i++];232                    ss << LOG_COL_DEFAULT;233                    if (fmt[i] == 0) break;234                }235                ss << fmt[i];236            }237            const size_t n = vsnprintf(entry.msg.data(), entry.msg.size(), ss.str().c_str(), args);238            if (n >= entry.msg.size()) {239                entry.msg.resize(n + 1);240                vsnprintf(entry.msg.data(), entry.msg.size(), ss.str().c_str(), args_copy);241            }242#endif243            va_end(args_copy);244        }245 246        entry.is_end    = false;247        entry.level     = level;248        entry.prefix    = prefix;249        entry.timestamp = 0;250        if (timestamps) {251            entry.timestamp = t_us() - t_start;252        }253 254        tail = (tail + 1) % queue.size();255        cv_new.notify_one();256    }257 258    void resume() {259        std::lock_guard<std::mutex> lock(mtx);260 261        if (running) {262            return;263        }264 265        running = true;266 267        thrd = std::thread([this]() {268            while (true) {269                std::unique_lock<std::mutex> lock(mtx);270                cv_new.wait(lock, [this]() { return !is_empty(); });271 272                size_t cached_head = head;273                size_t cached_tail = tail;274 275                lock.unlock(); // drop the lock during flush276 277                size_t next_head;278                bool stop = flush_queue(cached_head, cached_tail, next_head);279 280                lock.lock();281                head = next_head;282                cv_full.notify_all();283 284                if (stop) {285                    break;286                }287            }288        });289    }290 291    void pause() {292        {293            std::lock_guard<std::mutex> lock(mtx);294 295            if (!running) {296                return;297            }298 299            running = false;300 301            // push an entry to signal the worker thread to stop302            auto & entry = queue[tail];303            entry.is_end = true;304            tail = (tail + 1) % queue.size();305 306            // wakeup everyone307            cv_new.notify_one();308            cv_full.notify_all();309        }310 311        thrd.join();312    }313 314    void set_file(const char * path) {315        pause();316 317        if (file) {318            fclose(file);319        }320 321        if (path) {322            file = fopen(path, "w");323        } else {324            file = nullptr;325        }326 327        resume();328    }329 330    void set_colors(bool colors) {331        pause();332 333        if (colors) {334            g_col[COMMON_LOG_COL_DEFAULT] = LOG_COL_DEFAULT;335            g_col[COMMON_LOG_COL_BOLD]    = LOG_COL_BOLD;336            g_col[COMMON_LOG_COL_RED]     = LOG_COL_RED;337            g_col[COMMON_LOG_COL_GREEN]   = LOG_COL_GREEN;338            g_col[COMMON_LOG_COL_YELLOW]  = LOG_COL_YELLOW;339            g_col[COMMON_LOG_COL_BLUE]    = LOG_COL_BLUE;340            g_col[COMMON_LOG_COL_MAGENTA] = LOG_COL_MAGENTA;341            g_col[COMMON_LOG_COL_CYAN]    = LOG_COL_CYAN;342            g_col[COMMON_LOG_COL_WHITE]   = LOG_COL_WHITE;343        } else {344            for (size_t i = 0; i < std::size(g_col); i++) {345                g_col[i] = "";346            }347        }348 349        resume();350    }351 352    void set_prefix(bool prefix) {353        std::lock_guard<std::mutex> lock(mtx);354 355        this->prefix = prefix;356    }357 358    void set_timestamps(bool timestamps) {359        std::lock_guard<std::mutex> lock(mtx);360 361        this->timestamps = timestamps;362    }363};364 365//366// public API367//368 369struct common_log * common_log_init() {370    return new common_log;371}372 373struct common_log * common_log_main() {374    // We intentionally leak (i.e. do not delete) the logger singleton because375    // common_log destructor called at DLL teardown phase will cause hanging on Windows.376    // OS will release resources anyway so it should not be a significant issue,377    // though this design may cause logs to be lost if not flushed before the program exits.378    // Refer to https://github.com/ggml-org/llama.cpp/issues/22142 for details.379    static struct common_log * log;380    static std::once_flag    init_flag;381    std::call_once(init_flag, [&]() {382        log = new common_log;383        // Set default to auto-detect colors384        log->set_colors(tty_can_use_colors());385    });386 387    return log;388}389 390void common_log_pause(struct common_log * log) {391    log->pause();392}393 394void common_log_resume(struct common_log * log) {395    log->resume();396}397 398void common_log_free(struct common_log * log) {399    delete log;400}401 402void common_log_add(struct common_log * log, enum ggml_log_level level, const char * fmt, ...) {403    va_list args;404    va_start(args, fmt);405    log->add(level, fmt, args);406    va_end(args);407}408 409void common_log_set_file(struct common_log * log, const char * file) {410    log->set_file(file);411}412 413void common_log_set_colors(struct common_log * log, log_colors colors) {414    if (colors == LOG_COLORS_AUTO) {415        log->set_colors(tty_can_use_colors());416        return;417    }418 419    if (colors == LOG_COLORS_DISABLED) {420        log->set_colors(false);421        return;422    }423 424    GGML_ASSERT(colors == LOG_COLORS_ENABLED);425    log->set_colors(true);426}427 428void common_log_set_prefix(struct common_log * log, bool prefix) {429    log->set_prefix(prefix);430}431 432void common_log_set_timestamps(struct common_log * log, bool timestamps) {433    log->set_timestamps(timestamps);434}435 436void common_log_flush(struct common_log * log) {437    log->pause();438    log->resume();439}440 441static int common_get_verbosity(enum ggml_log_level level) {442    switch (level) {443        case GGML_LOG_LEVEL_DEBUG: return LOG_LEVEL_DEBUG;444        case GGML_LOG_LEVEL_INFO:  return LOG_LEVEL_TRACE;445        case GGML_LOG_LEVEL_WARN:  return LOG_LEVEL_WARN;446        case GGML_LOG_LEVEL_ERROR: return LOG_LEVEL_ERROR;447        case GGML_LOG_LEVEL_CONT:  return LOG_LEVEL_TRACE;448        case GGML_LOG_LEVEL_NONE:449        default:450            return LOG_LEVEL_OUTPUT;451    }452}453 454void common_log_default_callback(enum ggml_log_level level, const char * text, void * /*user_data*/) {455    auto verbosity = common_get_verbosity(level);456    if (verbosity <= common_log_verbosity_thold) {457        common_log_add(common_log_main(), level, "%s", text);458    }459}460