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:%lld:%lld:%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:%lld, %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:%lld %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: %lld \"%s\" l %ld:%lld %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: %lld \"%s\" c%d %ld:%lld %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: %lld \"%s\" %c%d %ld:%lld:%lld:\"%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 }; 438