+int
+sample_sc(void)
+{
+ kd_buf *kd, *end_of_sample;
+ int keep_going = 1;
+ int i;
+ ssize_t count;
+
+ if (!RAW_flag) {
+ /*
+ * Get kernel buffer information
+ */
+ get_bufinfo(&bufinfo);
+ }
+ if (need_new_map) {
+ delete_all_thread_entries();
+ read_command_map();
+ need_new_map = 0;
+ }
+ if (RAW_flag) {
+ ssize_t bytes_read;
+
+ bytes_read = read(RAW_fd, my_buffer, num_entries * sizeof(kd_buf));
+
+ if (bytes_read == -1) {
+ perror("read failed");
+ exit(2);
+ }
+ count = bytes_read / sizeof(kd_buf);
+
+ if (count != num_entries) {
+ keep_going = 0;
+ }
+
+ if (first_read) {
+ kd = (kd_buf *)my_buffer;
+ first_now = kd->timestamp & KDBG_TIMESTAMP_MASK;
+ first_read = 0;
+ }
+
+ } else {
+ int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDREADTR };
+ size_t needed = bufinfo.nkdbufs * sizeof(kd_buf);
+
+ if (sysctl(mib, ARRAYSIZE(mib), my_buffer, &needed, NULL, 0) < 0) {
+ quit("trace facility failure, KERN_KDREADTR\n");
+ }
+
+ count = needed;
+ sample_generation++;
+
+ if (bufinfo.flags & KDBG_WRAPPED) {
+ need_new_map = 1;
+
+ if (log_fp) {
+ fprintf(log_fp, "\n\n%-19.19s sample = %d <<<<<<< trace buffer wrapped >>>>>>>\n\n",
+ &(ctime(&curr_time)[0]), sample_generation);
+ }
+ set_enable(0);
+ set_enable(1);
+ }
+ }
+ end_of_sample = &((kd_buf *)my_buffer)[count];
+
+ /*
+ * Always reinitialize the DECR_TRAP array
+ */
+ for (i = 0; i < num_cpus; i++) {
+ last_decrementer_kd[i] = (kd_buf *)my_buffer;
+ }
+
+ for (kd = (kd_buf *)my_buffer; kd < end_of_sample; kd++) {
+ kd_buf *kd_start;
+ uintptr_t thread = kd->arg5;
+ int type = kd->debugid & DBG_FUNC_MASK;
+
+ (void)check_for_thread_update(thread, type, kd, NULL);
+
+ uint64_t now = kd->timestamp & KDBG_TIMESTAMP_MASK;
+ last_now = now;
+
+ if (type == DECR_TRAP) {
+ int cpunum = CPU_NUMBER(kd);
+ double i_latency = handle_decrementer(kd, cpunum);
+
+ if (log_fp) {
+ if (i_thresh_hold && (int)i_latency > i_thresh_hold) {
+ kd_start = last_decrementer_kd[cpunum];
+
+ log_decrementer(kd_start, kd, end_of_sample, i_latency);
+ }
+ last_decrementer_kd[cpunum] = kd;
+ }
+ } else {
+ double s_latency;
+ int s_priority;
+ if (check_for_scheduler_latency(type, &thread, now, kd, &kd_start, &s_priority, &s_latency)) {
+ log_scheduler(kd_start, kd, end_of_sample, s_priority, s_latency, thread);
+ }
+ }
+ }
+ if (log_fp) {
+ fflush(log_fp);
+ }
+
+ gc_thread_entries();
+ gc_reset_entries();
+ gc_run_events();
+
+ return keep_going;
+}
+
+void
+enter_syscall(FILE *fp, kd_buf *kd, uintptr_t thread, int type, char *command, uint64_t now, uint64_t idelta, uint64_t start_bias, int print_info)
+{
+ char *p;
+ double timestamp;
+ double delta;
+ char pcstring[128];
+
+ int cpunum = CPU_NUMBER(kd);
+
+ if (print_info && fp) {
+ timestamp = (double)(now - start_bias) / divisor;
+ delta = (double)idelta / divisor;
+
+ if ((p = find_code(type))) {
+ if (type == INTERRUPT) {
+ int mode;
+
+ if (kd->arg3) {
+ mode = USER_MODE;
+ } else {
+ mode = KERNEL_MODE;
+ }
+
+ pc_to_string(&pcstring[0], kd->arg2, 58, mode);
+
+ fprintf(fp, "%9.1f %8.1f\t\tINTERRUPT[%2lx] @ %-58.58s %8lx %2d %s\n",
+ timestamp, delta, kd->arg1, &pcstring[0], thread, cpunum, command);
+ } else if (type == MACH_vmfault) {
+ fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %8lx %2d %s\n",
+ timestamp, delta, p, thread, cpunum, command);
+ } else {
+ fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %-16lx %-16lx %-16lx %-16lx %8lx %2d %s\n",
+ timestamp, delta, p, kd->arg1, kd->arg2, kd->arg3, kd->arg4,
+ thread, cpunum, command);
+ }
+ } else {
+ fprintf(fp, "%9.1f %8.1f\t\t%-8x %-16lx %-16lx %-16lx %-16lx %8lx %2d %s\n",
+ timestamp, delta, type, kd->arg1, kd->arg2, kd->arg3, kd->arg4,
+ thread, cpunum, command);
+ }
+ }
+ if (type != BSC_thread_terminate && type != BSC_exit) {
+ insert_start_event(thread, type, now);
+ }
+}
+
+void
+exit_syscall(FILE *fp, kd_buf *kd, uintptr_t thread, int type, char *command, uint64_t now, uint64_t idelta, uint64_t start_bias, int print_info)
+{
+ char *p;
+ uint64_t user_addr;
+ double timestamp;
+ double delta;
+ double elapsed_timestamp;
+
+ elapsed_timestamp = (double)consume_start_event(thread, type, now) / divisor;
+
+ if (print_info && fp) {
+ int cpunum = CPU_NUMBER(kd);
+
+ timestamp = (double)(now - start_bias) / divisor;
+ delta = (double)idelta / divisor;
+
+ fprintf(fp, "%9.1f %8.1f(%.1f) \t", timestamp, delta, elapsed_timestamp);
+
+ if ((p = find_code(type))) {
+ if (type == INTERRUPT) {
+ fprintf(fp, "INTERRUPT %8lx %2d %s\n", thread, cpunum, command);
+ } else if (type == MACH_vmfault && kd->arg4 <= DBG_PAGEIND_FAULT) {
+ user_addr = ((uint64_t)kd->arg1 << 32) | (uint32_t)kd->arg2;
+
+ fprintf(fp, "%-28.28s %-10.10s %-16qx %8lx %2d %s\n",
+ p, fault_name[kd->arg4], user_addr,
+ thread, cpunum, command);
+ } else {
+ fprintf(fp, "%-28.28s %-16lx %-16lx %8lx %2d %s\n",
+ p, kd->arg1, kd->arg2,
+ thread, cpunum, command);
+ }
+ } else {
+ fprintf(fp, "%-8x %-16lx %-16lx %8lx %2d %s\n",
+ type, kd->arg1, kd->arg2,
+ thread, cpunum, command);
+ }
+ }
+}
+
+void
+print_entry(FILE *fp, kd_buf *kd, uintptr_t thread, int type, char *command, uint64_t now, uint64_t idelta, uint64_t start_bias, kd_buf *kd_note)
+{
+ char *p;
+
+ if (!fp) {
+ return;
+ }
+
+ int cpunum = CPU_NUMBER(kd);
+
+ double timestamp = (double)(now - start_bias) / divisor;
+ double delta = (double)idelta / divisor;
+
+ if ((p = find_code(type))) {
+ if (kd == kd_note) {
+ fprintf(fp, "%9.1f %8.1f\t**\t", timestamp, delta);
+ } else {
+ fprintf(fp, "%9.1f %8.1f\t\t", timestamp, delta);
+ }
+ fprintf(fp, "%-28.28s %-16lx %-16lx %-16lx %-16lx %8lx %2d %s\n",
+ p, kd->arg1, kd->arg2, kd->arg3, kd->arg4, thread, cpunum, command);
+ } else {
+ fprintf(fp, "%9.1f %8.1f\t\t%-8x %-16lx %-16lx %-16lx %-16lx %8lx %2d %s\n",
+ timestamp, delta, type, kd->arg1, kd->arg2, kd->arg3, kd->arg4,
+ thread, cpunum, command);
+ }
+}
+
+void
+check_for_thread_update(uintptr_t thread, int debugid_base, kd_buf *kbufp, char **command)
+{
+ if (debugid_base == TRACE_DATA_NEWTHREAD) {
+ /*
+ * Save the create thread data
+ */
+ create_tmp_map_entry(kbufp->arg1, thread);
+ } else if (debugid_base == TRACE_STRING_NEWTHREAD) {
+ /*
+ * process new map entry
+ */
+ find_and_insert_tmp_map_entry(thread, (char *)&kbufp->arg1);
+ } else if (debugid_base == TRACE_STRING_EXEC) {
+ exec_thread_entry(thread, (char *)&kbufp->arg1);
+ } else {
+ if (debugid_base == BSC_exit || debugid_base == BSC_thread_terminate) {
+ record_thread_entry_for_gc(thread);
+ }
+ if (command) {
+ find_thread_name(thread, command);
+ }
+ }
+}
+
+void
+log_info(uint64_t now, uint64_t idelta, uint64_t start_bias, kd_buf *kd, kd_buf *kd_note)
+{
+ lookup_t lkp;
+ int mode;
+ uintptr_t reason;
+ char *p;
+ char *command;
+ char *command1;
+ char command_buf[32];
+ char sched_info[64];
+ char pcstring[128];
+ const char *sched_reason;
+ double i_latency;
+ double timestamp;
+ double delta;
+ char joe[32];
+
+ uintptr_t thread = kd->arg5;
+ int cpunum = CPU_NUMBER(kd);
+ int debugid = kd->debugid;
+ int type = kd->debugid & DBG_FUNC_MASK;
+
+ (void)check_for_thread_update(thread, type, kd, &command);
+
+ if ((type >> 24) == DBG_TRACE) {
+ if (((type >> 16) & 0xff) != DBG_TRACE_INFO) {
+ return;
+ }
+ }
+ timestamp = (double)(now - start_bias) / divisor;
+ delta = (double)idelta / divisor;
+
+ switch (type) {
+
+ case CQ_action:
+ pc_to_string(&pcstring[0], kd->arg1, 84, KERNEL_MODE);
+
+ fprintf(log_fp, "%9.1f %8.1f\t\tCQ_action @ %-84.84s %8lx %2d %s\n",
+ timestamp, delta, &pcstring[0], thread, cpunum, command);
+ break;
+
+ case TES_action:
+ pc_to_string(&pcstring[0], kd->arg1, 83, KERNEL_MODE);
+
+ fprintf(log_fp, "%9.1f %8.1f\t\tTES_action @ %-83.83s %8lx %2d %s\n",
+ timestamp, delta, &pcstring[0], thread, cpunum, command);
+ break;
+
+ case IES_action:
+ pc_to_string(&pcstring[0], kd->arg1, 83, KERNEL_MODE);
+
+ fprintf(log_fp, "%9.1f %8.1f\t\tIES_action @ %-83.83s %8lx %2d %s\n",
+ timestamp, delta, &pcstring[0], thread, cpunum, command);
+ break;
+
+ case IES_filter:
+ pc_to_string(&pcstring[0], kd->arg1, 83, KERNEL_MODE);
+
+ fprintf(log_fp, "%9.1f %8.1f\t\tIES_filter @ %-83.83s %8lx %2d %s\n",
+ timestamp, delta, &pcstring[0], thread, cpunum, command);
+ break;
+
+ case DECR_TRAP:
+ if ((int)kd->arg1 >= 0) {
+ i_latency = 0;
+ } else {
+ i_latency = (((double)(-1 - kd->arg1)) / divisor);
+ }
+
+ if (i_thresh_hold && (int)i_latency > i_thresh_hold) {
+ p = "*";
+ } else {
+ p = " ";
+ }
+
+ if (kd->arg3) {
+ mode = USER_MODE;
+ } else {
+ mode = KERNEL_MODE;
+ }
+
+ pc_to_string(&pcstring[0], kd->arg2, 84, mode);
+
+ fprintf(log_fp, "%9.1f %8.1f[%.1f]%s\tDECR_TRAP @ %-84.84s %8lx %2d %s\n",
+ timestamp, delta, i_latency, p, &pcstring[0], thread, cpunum, command);
+ break;
+
+ case DECR_SET:
+ fprintf(log_fp, "%9.1f %8.1f[%.1f] \t%-28.28s %8lx %2d %s\n",
+ timestamp, delta, (double)kd->arg1/divisor, "DECR_SET", thread, cpunum, command);
+ break;
projects / apple / system_cmds.git / blobdiff