src/add-ons/kernel/file_cache/log.cpp

   1 /*
   2  * Copyright 2004-2005, Axel Dörfler, axeld@pinc-software.de. All rights reserved.
   3  * Distributed under the terms of the MIT License.
   4  */
   5
   6
   7 #include <KernelExport.h>
   8
   9 #include <util/kernel_cpp.h>
  10 #include <thread.h>
  11 #include <file_cache.h>
  12 #include <fs/fd.h>
  13 #include <generic_syscall.h>
  14
  15 #include <unistd.h>
  16 #include <stdlib.h>
  17 #include <string.h>
  18 #include <stdio.h>
  19 #include <errno.h>
  20
  21
  22 //#define TRACE_CACHE_MODULE
  23 #ifdef TRACE_CACHE_MODULE
  24 #       define TRACE(x) dprintf x
  25 #else
  26 #       define TRACE(x) ;
  27 #endif
  28
  29
  30 // generic syscall interface
  31 #define CACHE_LOG_SYSCALLS "cache_log"
  32 #define CACHE_LOG_SET_MODULE    1
  33
  34
  35 struct cache_log {
  36         team_id         team;
  37         char            team_name[B_OS_NAME_LENGTH];
  38         mount_id        device;
  39         vnode_id        parent;
  40         vnode_id        node;
  41         union {
  42                 char    file_name[B_FILE_NAME_LENGTH];
  43                 struct {
  44                         char    **args;
  45                         int32   arg_count;
  46                         team_id parent;
  47                 }               launch;
  48                 int32   access_type;
  49         };
  50         bigtime_t       timestamp;
  51         uint8           type;
  52         uint8           action;
  53 };
  54
  55 static const bigtime_t kLogTimeout = 50000;     // 50 ms
  56 static const int32 kLogWriterFrequency = 1;     // every tenth second
  57 static const uint32 kNumLogEntries = 6000;
  58 static const uint32 kLogWriteThreshold = 2000;
  59
  60 static struct cache_log sLogEntries[kNumLogEntries];
  61 static uint32 sCurrentEntry;
  62 static sem_id sLogEntrySem;
  63 static struct mutex sLock;
  64 static int sLogFile;
  65 static struct cache_module_info *sCacheModule;
  66
  67
  68 static void
  69 put_log_entry(cache_log *log)
  70 {
  71         mutex_unlock(&sLock);
  72 }
  73
  74
  75 static cache_log *
  76 get_log_entry()
  77 {
  78         if (acquire_sem_etc(sLogEntrySem, 1, B_RELATIVE_TIMEOUT, kLogTimeout) != B_OK) {
  79                 dprintf("log: Dropped log entry!\n");
  80                 return NULL;
  81         }
  82
  83         mutex_lock(&sLock);
  84         cache_log *log = &sLogEntries[sCurrentEntry++];
  85
  86         Thread *thread = thread_get_current_thread();
  87         log->team = thread->team->id;
  88         strlcpy(log->team_name, thread->name, B_OS_NAME_LENGTH);
  89
  90         log->timestamp = system_time();
  91
  92         return log;
  93 }
  94
  95
  96 static void
  97 log_node_opened(void *vnode, int32 fdType, mount_id device, vnode_id parent,
  98         vnode_id node, const char *name, off_t size)
  99 {
 100         cache_log *log = get_log_entry();
 101         if (log == NULL)
 102                 return;
 103
 104         if (name != NULL)
 105                 strlcpy(log->file_name, name, B_FILE_NAME_LENGTH);
 106         else {
 107                 log->file_name[0] = '\0';
 108                 vfs_get_vnode_name(vnode, log->file_name, B_FILE_NAME_LENGTH);
 109         }
 110         log->action = 'o';
 111         log->type = fdType;
 112
 113         log->device = device;
 114         log->parent = parent;
 115         log->node = node;
 116         log->timestamp = system_time();
 117
 118         TRACE(("log: added entry %s, <%c%d> %ld:%Ld:%Ld:%s\n", log->team_name, log->action,
 119                 log->type, device, parent, node, log->file_name));
 120
 121         put_log_entry(log);
 122
 123         if (sCacheModule != NULL && sCacheModule->node_opened != NULL)
 124                 sCacheModule->node_opened(vnode, fdType, device, parent, node, name, size);
 125 }
 126
 127
 128 static void
 129 log_node_closed(void *vnode, int32 fdType, mount_id device, vnode_id node, int32 accessType)
 130 {
 131         cache_log *log = get_log_entry();
 132         if (log == NULL)
 133                 return;
 134
 135         log->action = 'c';
 136         log->type = fdType;
 137
 138         log->device = device;
 139         log->parent = -1;
 140         log->node = node;
 141
 142         log->access_type = accessType;
 143
 144         TRACE(("log: added entry %s, <c%d> %ld:%Ld, %ld\n",
 145                 log->team_name, log->type, device, node, accessType));
 146
 147         put_log_entry(log);
 148
 149         if (sCacheModule != NULL && sCacheModule->node_closed != NULL)
 150                 sCacheModule->node_closed(vnode, fdType, device, node, accessType);
 151 }
 152
 153
 154 static void
 155 log_node_launched(size_t argCount, char * const *args)
 156 {
 157         cache_log *log = get_log_entry();
 158         if (log == NULL)
 159                 return;
 160
 161         log->action = 'l';
 162         log->type = FDTYPE_FILE;
 163
 164         log->launch.args = (char **)malloc(argCount * sizeof(char *));
 165         log->launch.arg_count = argCount;
 166
 167         for (uint32 i = 0; i < argCount; i++) {
 168                 if  (i == 0) {
 169                         // cut off path from parent team name
 170                         Team *team = thread_get_current_thread()->team;
 171                         char name[B_OS_NAME_LENGTH];
 172                         cpu_status state;
 173
 174                         state = disable_interrupts();
 175                         GRAB_TEAM_LOCK();
 176
 177                         log->launch.parent = team->parent->id;
 178                         strlcpy(name, team->parent->main_thread->name, B_OS_NAME_LENGTH);
 179
 180                         RELEASE_TEAM_LOCK();
 181                         restore_interrupts(state);
 182
 183                         log->launch.args[0] = strdup(name);
 184                 } else
 185                         log->launch.args[i] = strdup(args[i]);
 186
 187                 // remove newlines from the arguments
 188                 char *newline;
 189                 while ((newline = strchr(log->launch.args[i], '\n')) != NULL) {
 190                         *newline = ' ';
 191                 }
 192         }
 193
 194         if (vfs_get_cwd(&log->device, &log->parent) != B_OK) {
 195                 log->device = -1;
 196                 log->parent = -1;
 197         }
 198
 199         TRACE(("log: added entry %s, <l> %ld:%Ld %s ...\n", log->team_name,
 200                 log->device, log->parent, args[0]));
 201
 202         put_log_entry(log);
 203
 204         if (sCacheModule != NULL && sCacheModule->node_launched != NULL)
 205                 sCacheModule->node_launched(argCount, args);
 206 }
 207
 208
 209 static status_t
 210 log_control(const char *subsystem, uint32 function,
 211         void *buffer, size_t bufferSize)
 212 {
 213         switch (function) {
 214                 case CACHE_LOG_SET_MODULE:
 215                 {
 216                         cache_module_info *module = sCacheModule;
 217
 218                         // unset previous module
 219
 220                         if (sCacheModule != NULL) {
 221                                 sCacheModule = NULL;
 222                                 snooze(100000); // 0.1 secs
 223                                 put_module(module->info.name);
 224                         }
 225
 226                         // get new module, if any
 227
 228                         if (buffer == NULL)
 229                                 return B_OK;
 230
 231                         char name[B_FILE_NAME_LENGTH];
 232                         if (!IS_USER_ADDRESS(buffer)
 233                                 || user_strlcpy(name, (char *)buffer, B_FILE_NAME_LENGTH) < B_OK)
 234                                 return B_BAD_ADDRESS;
 235
 236                         if (strncmp(name, CACHE_MODULES_NAME, strlen(CACHE_MODULES_NAME)))
 237                                 return B_BAD_VALUE;
 238
 239                         TRACE(("log_control: set module %s!\n", name));
 240
 241                         status_t status = get_module(name, (module_info **)&module);
 242                         if (status == B_OK)
 243                                 sCacheModule = module;
 244
 245                         return status;
 246                 }
 247         }
 248
 249         return B_BAD_HANDLER;
 250 }
 251
 252
 253 static void
 254 log_writer_daemon(void *arg, int /*iteration*/)
 255 {
 256         mutex_lock(&sLock);
 257
 258         if (sCurrentEntry > kLogWriteThreshold || arg != NULL) {
 259                 off_t fileSize = 0;
 260                 struct stat stat;
 261                 if (fstat(sLogFile, &stat) == 0) {
 262                         // enlarge file, so that it can be written faster
 263                         fileSize = stat.st_size;
 264                         ftruncate(sLogFile, fileSize + 512 * 1024);
 265                 } else
 266                         stat.st_size = -1;
 267
 268                 for (uint32 i = 0; i < sCurrentEntry; i++) {
 269                         cache_log *log = &sLogEntries[i];
 270                         char line[1236];
 271                         ssize_t length = 0;
 272
 273                         switch (log->action) {
 274                                 case 'l':       // launch
 275                                         length = snprintf(line, sizeof(line), "%ld: %Ld \"%s\" l %ld:%Ld %ld \"%s\" ",
 276                                                                 log->team, log->timestamp, log->team_name,
 277                                                                 log->device, log->parent, log->launch.parent,
 278                                                                 log->launch.args[0]);
 279                                         length = std::min(length, (ssize_t)sizeof(line) - 1);
 280
 281                                         for (int32 j = 1; j < log->launch.arg_count; j++) {
 282                                                 // write argument list one by one, so that we can deal
 283                                                 // with very long argument lists
 284                                                 ssize_t written = write(sLogFile, line, length);
 285                                                 if (written != length) {
 286                                                         dprintf("log: must drop log entries: %ld, %s!\n",
 287                                                                 written, strerror(written));
 288                                                         break;
 289                                                 } else
 290                                                         fileSize += length;
 291
 292                                                 strlcpy(line, log->launch.args[j], sizeof(line));
 293                                                 length = strlcat(line, "\xb0 ", sizeof(line));
 294                                         }
 295
 296                                         if (length >= (ssize_t)sizeof(line))
 297                                                 length = sizeof(line) - 1;
 298
 299                                         line[length - 1] = '\n';
 300                                         break;
 301
 302                                 case 'c':       // close
 303                                         length = snprintf(line, sizeof(line), "%ld: %Ld \"%s\" c%d %ld:%Ld %ld\n",
 304                                                 log->team, log->timestamp, log->team_name, log->type,
 305                                                 log->device, log->node, log->access_type);
 306                                         length = std::min(length, (ssize_t)sizeof(line) - 1);
 307                                         break;
 308
 309                                 default:        // open, ?
 310                                         length = snprintf(line, sizeof(line), "%ld: %Ld \"%s\" %c%d %ld:%Ld:%Ld:\"%s\"\n",
 311                                                 log->team, log->timestamp, log->team_name, log->action, log->type, log->device,
 312                                                 log->parent, log->node, log->file_name);
 313                                         length = std::min(length, (ssize_t)sizeof(line) - 1);
 314                                         break;
 315                         }
 316
 317                         ssize_t written = write(sLogFile, line, length);
 318                         if (written != length) {
 319                                 dprintf("log: must drop log entries: %ld, %s!\n", written, strerror(written));
 320                                 break;
 321                         } else
 322                                 fileSize += length;
 323                 }
 324
 325                 // shrink file again to its real size
 326                 if (stat.st_size != -1)
 327                         ftruncate(sLogFile, fileSize);
 328
 329                 // need to free any launch log items (also if writing fails)
 330
 331                 for (uint32 i = 0; i < sCurrentEntry; i++) {
 332                         cache_log *log = &sLogEntries[i];
 333                         if (log->action != 'l')
 334                                 continue;
 335
 336                         for (int32 j = 0; j < log->launch.arg_count; j++)
 337                                 free(log->launch.args[j]);
 338
 339                         free(log->launch.args);
 340                 }
 341
 342                 release_sem_etc(sLogEntrySem, sCurrentEntry, B_DO_NOT_RESCHEDULE);
 343                 sCurrentEntry = 0;
 344         }
 345
 346         mutex_unlock(&sLock);
 347 }
 348
 349
 350 static void
 351 uninit_log(void)
 352 {
 353         TRACE(("** log uninit - \n"));
 354
 355         unregister_kernel_daemon(log_writer_daemon, NULL);
 356         unregister_generic_syscall(CACHE_LOG_SYSCALLS, 1);
 357
 358         log_writer_daemon((void *)true, 0);
 359                 // flush log entries
 360
 361         delete_sem(sLogEntrySem);
 362         mutex_destroy(&sLock);
 363         close(sLogFile);
 364
 365         if (sCacheModule != NULL)
 366                 put_module(sCacheModule->info.name);
 367
 368         TRACE(("** - log uninit\n"));
 369 }
 370
 371
 372 static status_t
 373 init_log(void)
 374 {
 375         TRACE(("** log init\n"));
 376
 377         int32 number = 0;
 378         do {
 379                 char name[B_FILE_NAME_LENGTH];
 380                 snprintf(name, sizeof(name), "/var/log/cache_%03ld", number++);
 381
 382                 sLogFile = open(name, O_WRONLY | O_CREAT | O_EXCL, DEFFILEMODE);
 383         } while (sLogFile < 0 && errno == B_FILE_EXISTS);
 384
 385         if (sLogFile < B_OK) {
 386                 dprintf("log: opening log file failed: %s\n", strerror(errno));
 387                 return sLogFile;
 388         }
 389
 390         sLogEntrySem = create_sem(kNumLogEntries, "cache log entries");
 391         if (sLogEntrySem >= B_OK) {
 392                 mutex_init(&sLock, "log cache module");
 393                 register_kernel_daemon(log_writer_daemon, NULL, kLogWriterFrequency);
 394                 register_generic_syscall(CACHE_LOG_SYSCALLS, log_control, 1, 0);
 395
 396                 TRACE(("** - log init\n"));
 397                 return B_OK;
 398         }
 399
 400         close(sLogFile);
 401         return B_ERROR;
 402 }
 403
 404
 405 static status_t
 406 log_std_ops(int32 op, ...)
 407 {
 408         switch (op) {
 409                 case B_MODULE_INIT:
 410                         return init_log();
 411
 412                 case B_MODULE_UNINIT:
 413                         uninit_log();
 414                         return B_OK;
 415
 416                 default:
 417                         return B_ERROR;
 418         }
 419 }
 420
 421
 422 static struct cache_module_info sLogCacheModule = {
 423         {
 424                 CACHE_MODULES_NAME "/log/v1",
 425                 0,
 426                 log_std_ops,
 427         },
 428         log_node_opened,
 429         log_node_closed,
 430         log_node_launched,
 431 };
 432
 433
 434 module_info *modules[] = {
 435         (module_info *)&sLogCacheModule,
 436         NULL
 437 };