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 struct 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 struct 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 280 for (int32 j = 1; j < log->launch.arg_count; j++) { 281 // write argument list one by one, so that we can deal 282 // with very long argument lists 283 ssize_t written = write(sLogFile, line, length); 284 if (written != length) { 285 dprintf("log: must drop log entries: %ld, %s!\n", 286 written, strerror(written)); 287 break; 288 } else 289 fileSize += length; 290 291 strlcpy(line, log->launch.args[j], sizeof(line)); 292 length = strlcat(line, "\xb0 ", sizeof(line)); 293 } 294 295 if (length >= (ssize_t)sizeof(line)) 296 length = sizeof(line) - 1; 297 298 line[length - 1] = '\n'; 299 break; 300 301 case 'c': // close 302 length = snprintf(line, sizeof(line), "%ld: %Ld \"%s\" c%d %ld:%Ld %ld\n", 303 log->team, log->timestamp, log->team_name, log->type, 304 log->device, log->node, log->access_type); 305 break; 306 307 default: // open, ? 308 length = snprintf(line, sizeof(line), "%ld: %Ld \"%s\" %c%d %ld:%Ld:%Ld:\"%s\"\n", 309 log->team, log->timestamp, log->team_name, log->action, log->type, log->device, 310 log->parent, log->node, log->file_name); 311 break; 312 } 313 314 ssize_t written = write(sLogFile, line, length); 315 if (written != length) { 316 dprintf("log: must drop log entries: %ld, %s!\n", written, strerror(written)); 317 break; 318 } else 319 fileSize += length; 320 } 321 322 // shrink file again to its real size 323 if (stat.st_size != -1) 324 ftruncate(sLogFile, fileSize); 325 326 // need to free any launch log items (also if writing fails) 327 328 for (uint32 i = 0; i < sCurrentEntry; i++) { 329 cache_log *log = &sLogEntries[i]; 330 if (log->action != 'l') 331 continue; 332 333 for (int32 j = 0; j < log->launch.arg_count; j++) 334 free(log->launch.args[j]); 335 336 free(log->launch.args); 337 } 338 339 release_sem_etc(sLogEntrySem, sCurrentEntry, B_DO_NOT_RESCHEDULE); 340 sCurrentEntry = 0; 341 } 342 343 mutex_unlock(&sLock); 344 } 345 346 347 static void 348 uninit_log(void) 349 { 350 TRACE(("** log uninit - \n")); 351 352 unregister_kernel_daemon(log_writer_daemon, NULL); 353 unregister_generic_syscall(CACHE_LOG_SYSCALLS, 1); 354 355 log_writer_daemon((void *)true, 0); 356 // flush log entries 357 358 delete_sem(sLogEntrySem); 359 mutex_destroy(&sLock); 360 close(sLogFile); 361 362 if (sCacheModule != NULL) 363 put_module(sCacheModule->info.name); 364 365 TRACE(("** - log uninit\n")); 366 } 367 368 369 static status_t 370 init_log(void) 371 { 372 TRACE(("** log init\n")); 373 374 int32 number = 0; 375 do { 376 char name[B_FILE_NAME_LENGTH]; 377 snprintf(name, sizeof(name), "/var/log/cache_%03ld", number++); 378 379 sLogFile = open(name, O_WRONLY | O_CREAT | O_EXCL, DEFFILEMODE); 380 } while (sLogFile < 0 && errno == B_FILE_EXISTS); 381 382 if (sLogFile < B_OK) { 383 dprintf("log: opening log file failed: %s\n", strerror(errno)); 384 return sLogFile; 385 } 386 387 sLogEntrySem = create_sem(kNumLogEntries, "cache log entries"); 388 if (sLogEntrySem >= B_OK) { 389 mutex_init(&sLock, "log cache module"); 390 register_kernel_daemon(log_writer_daemon, NULL, kLogWriterFrequency); 391 register_generic_syscall(CACHE_LOG_SYSCALLS, log_control, 1, 0); 392 393 TRACE(("** - log init\n")); 394 return B_OK; 395 } 396 397 close(sLogFile); 398 return B_ERROR; 399 } 400 401 402 static status_t 403 log_std_ops(int32 op, ...) 404 { 405 switch (op) { 406 case B_MODULE_INIT: 407 return init_log(); 408 409 case B_MODULE_UNINIT: 410 uninit_log(); 411 return B_OK; 412 413 default: 414 return B_ERROR; 415 } 416 } 417 418 419 static struct cache_module_info sLogCacheModule = { 420 { 421 CACHE_MODULES_NAME "/log/v1", 422 0, 423 log_std_ops, 424 }, 425 log_node_opened, 426 log_node_closed, 427 log_node_launched, 428 }; 429 430 431 module_info *modules[] = { 432 (module_info *)&sLogCacheModule, 433 NULL 434 }; 435