macosx-10.10/BootCache-109/kext.c

155 # define debug(fmt, args...)	message("*** " fmt, ##args)
158 # define debug(fmt, args...)	do {} while (0)
326  * To be able to debug live read history *
660 	/* Racy, but used for debug output so who cares */
1146 			debug("disk %d starting low priority batch", cd->cd_disk_num);
1148 			debug("disk %d starting batch %d", cd->cd_disk_num, cd->cd_batch);
1198 					debug("Saw a regular extent while issuing throttled IO");
1284 						debug("Unable to update throttle info for mount %s: %d", uuid_string(cm->cm_uuid), error);
1316 						debug("read error: extent %lu %lu/%lu "
1324 						debug("read error: discarded %d bytes", count);
1388 					debug("New extents, interrupting low priority readahead");
1423 			// debug("disk %d low priority batch done", cd->cd_disk_num);
1425 			// debug("disk %d batch %d done", cd->cd_disk_num, cd->cd_batch);
1458 				debug("disk %d more mounts detected (%d total)", cd->cd_disk_num, cd->cd_nmounts);
1511 	debug("disk %d done", cd->cd_disk_num);
1543 			debug("Tearing down closing mount %s with dev 0x%x", uuid_string(cm->cm_uuid), dev);
1753 //			debug("not recording %s%s from app %s for file %s (disk block 0x%llx) which is%s throttled", (vp && vnode_israge(vp)) ? "rapid age " : "", (bufflags & B_READ) ? "read" : "write", procname, filename?:"unknown", blkno, (bufflags & B_THROTTLED_IO) ? "" : " not");
1811 		debug("IO with non-blocksize multiple bytes (%d %% %lld = %lld)", nbytes, BC_cache->c_mounts[cm_idx].cm_blocksize, (nbytes % BC_cache->c_mounts[cm_idx].cm_blocksize));
1949 					debug("Strategy routine timed out app %s waiting on file %s (disk offset 0x%llx) after %lu.%03d seconds", procname, filename?:"unknown", disk_offset, blocked_end_time.tv_sec, blocked_end_time.tv_usec / 1000);
1984 			debug("Strategy routine blocked app %s waiting on file %s (disk offset 0x%llx) for %lu.%03d seconds", procname, filename?:"unknown", disk_offset, blocked_end_time.tv_sec, blocked_end_time.tv_usec / 1000);
2013 		debug("vnode_getwithvid failed - %d", kret);
2087 			debug("couldn't allocate uio");
2097 			debug("couldn't add iov to uio - %d", kret);
2107 			debug("couldn't copy ubc data - %d", kret);
2319 				debug("detected %s swap file, jettisoning cache", (bufflags & B_READ) ? "read from" : "write to");
2321 				debug("detected stolen page, jettisoning cache");
2345 					debug("hit rate below threshold (0 hits in the last %u lookups), jettisoning cache",
2356 		debug("Detected %s swap file. Terminating readahead", (bufflags & B_READ) ? "read from" : "write to");
2469 		debug("terminating active readahead");
2477 				debug("but I/O has stopped!");
2517 	debug("Kicking off thread to terminate cache");
2542 		debug("cannot terminate cache while readahead is in progress");
2551 		debug("cannot terminate cache when not active");
2559 	debug("terminating cache...");
2694 		debug("cannot terminate history when not active");
2699 	debug("terminating history collection...");
2746 		debug("Cannot check device handlers: cache not setup properly");
2757 			debug("connecting handlers...");
2767 			debug("disconnecting handlers...");
2811 		// debug("Largest batch is now %d from extent with disk offset %llu", BC_cache->c_batch_count, ce->ce_diskoffset);
2864         debug("Clipped extent %llu by a page", ce->ce_diskoffset);
2911 	debug("Setup disk 0x%llx as disk num %d%s", disk_id, cd->cd_disk_num, (cd->cd_flags & CD_IS_SSD) ? " (ssd)" : "");
2957 				debug("Interrupting low-priority thread for new mount %s", uuid_string(cm->cm_uuid));
2969 		debug("Kicking off reader thread for disk %d for mount %s", cd->cd_disk_num, uuid_string(cm->cm_uuid));
3078 	/* debug("Got throttle mask %llx for mount %s", cm->cm_throttle_mask, uuid_string(cm->cm_uuid)); */
3093 			debug("Root disk (via cache) is 0x%llx", BC_cache->c_root_disk_id);
3101 		debug("mount %s (disk 0x%llx) is not on the root disk (disk 0x%llx)", uuid_string(cm->cm_uuid), disk_id, BC_cache->c_root_disk_id);
3203 			debug("MAXBYTECOUNTREAD is %#llx", max_byte_count);
3215 			debug("MAXBLOCKCOUNTREAD is %#llx, BLOCKSIZE is %#llx, (multiplied %#llx)", max_block_count, cm->cm_blocksize, max_block_count * cm->cm_blocksize, cm->cm_maxread);
3235 					debug("MAXSEGMENTBYTECOUNTREAD is %#llx, limiting to PAGE_SIZE %#x", max_segment_byte_count, PAGE_SIZE);
3239 				debug("Unable to get MAXSEGMENTBYTECOUNTREAD, assuming PAGE_SIZE %#x", PAGE_SIZE);
3245 				debug("MAXSEGMENTCOUNTREAD is %#llx, MAXSEGMENTBYTECOUNTREAD is %#llx, (multiplied %#llx)", max_segment_count, max_segment_byte_count, max_segment_count * max_segment_byte_count);
3253 		debug("MAX_UPL_TRANSFER is %#x, PAGE_SIZE is %#x, (multiplied %#x)", MAX_UPL_TRANSFER, PAGE_SIZE, MAX_UPL_TRANSFER * PAGE_SIZE);
3258 		debug("can't determine device read size for mount %s; using default", uuid_string(cm->cm_uuid));
3264         debug("Mount max IO size (%llu) not a multiple of block size (%llu)", cm->cm_maxread, cm->cm_blocksize);
3295 	debug("Found new cache mount %s disk %d, %d extents", uuid_string(cm->cm_uuid), cm->cm_disk->cd_disk_num, cm->cm_nextents);
3359 			debug("Found mount %s for IO without a UUID: error %d", name, error);
3365 		// debug("Found mount for IO with UUID %s", uuid_string(attr.f_uuid));
3382 						debug("Found root mount %s", uuid_string(cm->cm_uuid));
3422 	debug("No new mounts filled in fill_in_bc_cache_mounts");
3502 		debug("adding %u extents to existing cache of %u extents", nplaylist_entries, BC_cache->c_stats.ss_total_extents);
3504 		debug("setting up first cache of %d extents", nplaylist_entries);
3508 		debug("Mount %s has %d extents", uuid_string(BC_cache->c_mounts[cm_idx].cm_uuid), BC_cache->c_mounts[cm_idx].cm_nextents);
3731 				debug("Bad Playlist: entry %d has 0 length", (nplaylist_entries - remaining_entries) + pe_idx);
3778 						debug("!!! Entry %d (0x%llx:%lld) is getting clipped too much because of previous entry for mount %s (0x%llx:%lld)", pe_idx, ce->ce_diskoffset, ce->ce_length, uuid_string(cm->cm_uuid), old_cm->cm_pextents[next_old_extent_idx[cm_idx]]->ce_diskoffset, old_cm->cm_pextents[next_old_extent_idx[cm_idx]]->ce_length);
3943 		debug("%d extents were clipped, %d of which were completely enveloped", clipped_extents, enveloped_extents);
3947 		debug("No extents added, not updating cache");
3958 		debug("%d extents added out of %d", ncache_extents, nplaylist_entries);
3961 		debug("Mount %s now has %d extents", uuid_string(cache_mounts[cm_idx].cm_uuid), cache_mounts[cm_idx].cm_nextents);
4079 				debug("Missing root mount during last iteration, going again");
4098 			debug("cache setup failed, aborting");
4145 	debug("BC_copyin_playlist took %ldus", end_time.tv_sec * 1000000 + end_time.tv_usec);
4164 		debug("Invalid cache parameters: %ld, %lld, %ld, %lld", mounts_size, mounts, entries_size, entries);
4170 		debug("Cache not yet setup");
4184 			debug("history recording already started, only one playlist will be returned");
4188 			debug("starting history recording");
4236 			debug("cache already shutdown");
4346 	debug("history recording timed out");
4376 		//debug("Mount %s (%p)'s vnode is NULL", name, mount);
4382 	//debug("Mount %s (%p)'s vnode %p's device is 0x%x", name, mount, devvp, mount_dev);
4413 			debug("Found mount %s without a UUID: error %d", name, error);
4428 		debug("can't determine if physical disk for history mount %s is an ssd", uuid_string(hmd->hmd_mount.hm_uuid));
4439 				debug("Root disk (via history) is 0x%llx", BC_cache->c_root_disk_id);
4442 			debug("Root disk 0x%llx doesn't match that found by history 0x%llx", BC_cache->c_root_disk_id, hmd->hmd_disk_id);
4449 	debug("Found new historic mount after %d IOs: %s, dev 0x%x, disk 0x%llx, blk %d%s",
4515 		debug("Missing root mount during last iteration, going again");
4631 		debug("History recording too large, capping at %lluMB", BC_MAX_SIZE / (1024 * 1024));
4638 	debug("history disabled, truncating");
4919 		debug("insufficient physical memory (%dMB < %dMB required)",
4939 	debug("Major of rootdev is %d", major(rootdev));
4947 		debug("cache was not terminated properly previously");
4974 		debug("BootCache setup failed: %d", error);
4989 		debug("BootCache autostart failed: %d", error);
4998 	debug("device unmounted");
5021 		debug("couldn't get command");
5025 		debug("bad command magic");
5031 			debug("BC_OP_START(%d mounts, %d extents)", (int)(bc.bc_data1_size / sizeof(struct BC_playlist_mount)), (int)(bc.bc_data2_size / sizeof(struct BC_playlist_entry)));
5043 			debug("BC_OP_STOP");
5056 				debug("could not return history size");
5062 			/* debug("BC_OP_MOUNT"); */
5071 			debug("BC_OP_HISTORY");
5077 					debug("supplied history buffer too small");
5083 					debug("could not copy out history mounts: %d", error);
5086 					debug("could not copy out history entries: %d", error);
5097 			debug("BC_OP_JETTISON");
5107 			debug("BC_OP_STATS");
5110 				debug("stats structure wrong size");
5115 					debug("could not copy out statistics");
5120 			debug("BC_OP_TAG");
5129 			debug("BC_OP_TEST");
5158 			debug("vnode_open failed - %d", kret);
5167 			debug("vnode_getwithvid failed - %d", ret);
5175 		debug("ubc_setsize failed - %d", kret);
5196 			debug("vnode_getwithref failed - %d", kret);
5203 			debug("ubc_range_op failed - %d", kret);
5211 			debug("vnode_delete failed - %d", error);
5216 			debug("vnode_close failed - %d", kret);
5235 		debug("vnode_getwithvid failed - %d", kret);
5242 		debug("ubc_range_op failed - %d", kret);
5254 		debug("BootCache setup failed: %d", error);
5310 	debug("preload section %s: %d @ %p",
5335 		debug("waiting for root mount...");
5340 		debug("waiting for playlist...");
5351 	debug("preparing to unload...");