diff --git a/src/XrdFileCache/XrdFileCache.cc b/src/XrdFileCache/XrdFileCache.cc index 674b164b3a2..accaaf8445b 100644 --- a/src/XrdFileCache/XrdFileCache.cc +++ b/src/XrdFileCache/XrdFileCache.cc @@ -146,18 +146,19 @@ XrdOucCacheIO2 *Cache::Attach(XrdOucCacheIO2 *io, int Options) { if (Cache::GetInstance().Decide(io)) { - clLog()->Info(XrdCl::AppMsg, "Cache::Attach() %s", io->Path()); + TRACE(Debug, "Cache::Attach() " << io->Path()); IO* cio; if (Cache::GetInstance().RefConfiguration().m_hdfsmode) cio = new IOFileBlock(io, m_stats, *this); else cio = new IOEntireFile(io, m_stats, *this); + TRACE(Info, "Cache::Attach() " << io->Path()); return cio; } else { - clLog()->Info(XrdCl::AppMsg, "Cache::Attach() reject %s", io->Path()); + TRACE(Info, "Cache::Attach() decision decline " << io->Path()); } return io; } @@ -172,7 +173,7 @@ int Cache::isAttached() void Cache::Detach(XrdOucCacheIO* io) { - clLog()->Info(XrdCl::AppMsg, "Cache::Detach() %s", io->Path()); + TRACE(Info, "Cache::Detach() " << io->Path()); // Cache owns File objects XrdSysMutexHelper lock(&m_active_mutex); @@ -200,7 +201,7 @@ Cache::HaveFreeWritingSlots() return true; } else { - XrdCl::DefaultEnv::GetLog()->Info(XrdCl::AppMsg, "Cache::HaveFreeWritingSlots() negative", m_writeQ.size); + TRACE(Dump, "Cache::HaveFreeWritingSlots() negative " << m_writeQ.size); return false; } } @@ -208,7 +209,7 @@ Cache::HaveFreeWritingSlots() void Cache::AddWriteTask(Block* b, bool fromRead) { - XrdCl::DefaultEnv::GetLog()->Dump(XrdCl::AppMsg, "Cache::AddWriteTask() bOff=%ld", b->m_offset); + TRACE(Dump, "Cache::AddWriteTask() bOff=%ld " << b->m_offset); m_writeQ.condVar.Lock(); if (fromRead) m_writeQ.queue.push_back(b); @@ -228,10 +229,9 @@ void Cache::RemoveWriteQEntriesFor(File *iFile) { if ((*i)->m_file == iFile) { - - XrdCl::DefaultEnv::GetLog()->Dump(XrdCl::AppMsg, "Cache::Remove entries for %p path %s", (void*)(*i), iFile->lPath()); + TRACE(Dump, "Cache::Remove entries for " << (void*)(*i) << " path " << iFile->lPath()); std::list::iterator j = i++; - iFile->BlockRemovedFromWriteQ(*j); + iFile->BlockRemovedFromWriteQ(*j); m_writeQ.queue.erase(j); --m_writeQ.size; } @@ -257,7 +257,7 @@ Cache::ProcessWriteTasks() Block* block = m_writeQ.queue.front(); // AMT should not be back ??? m_writeQ.queue.pop_front(); m_writeQ.size--; - XrdCl::DefaultEnv::GetLog()->Dump(XrdCl::AppMsg, "Cache::ProcessWriteTasks for %p path %s", (void*)(block), block->m_file->lPath()); + TRACE(Dump, "Cache::ProcessWriteTasks for %p " << (void*)(block) << " path " << block->m_file->lPath()); m_writeQ.condVar.UnLock(); block->m_file->WriteBlockToDisk(block); @@ -332,13 +332,10 @@ Cache::RegisterPrefetchFile(File* file) if (Cache::GetInstance().RefConfiguration().m_prefetch_max_blocks) { - - XrdCl::DefaultEnv::GetLog()->Dump(XrdCl::AppMsg, "Cache::Register new file BEGIN"); m_prefetch_condVar.Lock(); m_prefetchList.push_back(file); m_prefetch_condVar.Signal(); m_prefetch_condVar.UnLock(); - XrdCl::DefaultEnv::GetLog()->Dump(XrdCl::AppMsg, "Cache::Register new file End"); } } @@ -399,7 +396,7 @@ Cache::Prepare(const char *url, int oflags, mode_t mode) struct stat buf; int res = m_output_fs->Stat(spath.c_str(), &buf); if (res == 0) { - XrdCl::DefaultEnv::GetLog()->Dump(XrdCl::AppMsg, "Cache::Prefetch defer open %s", spath.c_str()); + TRACE( Dump, "Cache::Prefetch defer open " << spath); return 1; } else { @@ -433,7 +430,7 @@ int Cache::Stat(const char *curl, struct stat &sbuff) name += ".cinfo"; int res = infoFile->Open(name.c_str(), O_RDONLY, 0600, myEnv); if (res >= 0) { - Info info(0); + Info info(m_trace, 0); if (info.Read(infoFile) > 0) { sbuff.st_size = info.GetFileSize(); success = true; @@ -455,9 +452,6 @@ void Cache::Prefetch() { int limitRAM= Cache::GetInstance().RefConfiguration().m_NRamBuffers * 0.7; - - XrdCl::DefaultEnv::GetLog()->Dump(XrdCl::AppMsg, "Cache::Prefetch thread start"); - while (true) { m_RAMblock_mutex.Lock(); bool doPrefetch = (m_RAMblocks_used < limitRAM && HaveFreeWritingSlots()); diff --git a/src/XrdFileCache/XrdFileCache.hh b/src/XrdFileCache/XrdFileCache.hh index 5f337a7b7f2..89249d83873 100644 --- a/src/XrdFileCache/XrdFileCache.hh +++ b/src/XrdFileCache/XrdFileCache.hh @@ -192,7 +192,7 @@ namespace XrdFileCache void AddActive(IO*, File*); - XrdOucTrace* GetTrace() { return m_trace; } + XrdOucTrace* GetTrace() { return m_trace; } private: bool ConfigParameters(std::string, XrdOucStream&); bool ConfigXeq(char *, XrdOucStream &); @@ -213,9 +213,6 @@ namespace XrdFileCache Configuration m_configuration; //!< configurable parameters - //! Short log alias. - XrdCl::Log* clLog() const { return XrdCl::DefaultEnv::GetLog(); } - XrdSysCondVar m_prefetch_condVar; //!< central lock for this class XrdSysMutex m_RAMblock_mutex; //!< central lock for this class diff --git a/src/XrdFileCache/XrdFileCacheConfiguration.cc b/src/XrdFileCache/XrdFileCacheConfiguration.cc index 69c9665be7b..06e3bc9b1f0 100644 --- a/src/XrdFileCache/XrdFileCacheConfiguration.cc +++ b/src/XrdFileCache/XrdFileCacheConfiguration.cc @@ -34,7 +34,7 @@ bool Cache::xdlib(XrdOucStream &Config) std::string libp; if (!(val = Config.GetWord()) || !val[0]) { - clLog()->Info(XrdCl::AppMsg, " Cache::Config() decisionlib not specified; always caching files"); + TRACE(Info," Cache::Config() decisionlib not specified; always caching files"); return true; } else @@ -55,14 +55,13 @@ bool Cache::xdlib(XrdOucStream &Config) Decision * d = ep(m_log); if (!d) { - clLog()->Error(XrdCl::AppMsg, "Cache::Config() decisionlib was not able to create a decision object"); + TRACE(Error, "Cache::Config() decisionlib was not able to create a decision object"); return false; } if (params) d->ConfigDecision(params); m_decisionpoints.push_back(d); - clLog()->Info(XrdCl::AppMsg, "Cache::Config() successfully created decision lib from %s", libp.c_str()); return true; } @@ -90,11 +89,12 @@ bool Cache::xtrace(XrdOucStream &Config) for (int i = 0; i < numopts; i++) { - if (!strcmp(val, tropts[i].opname)) + if (!strcmp(val, tropts[i].opname)) { m_trace->What = tropts[i].opval; - return true; + return true; + } } - return 0; + return false; } //______________________________________________________________________________ @@ -112,14 +112,14 @@ bool Cache::Config(XrdSysLogger *logger, const char *config_filename, const char if (!config_filename || !*config_filename) { - clLog()->Warning(XrdCl::AppMsg, "Cache::Config() configuration file not specified."); + TRACE(Error, "Cache::Config() configuration file not specified."); return false; } int fd; if ( (fd = open(config_filename, O_RDONLY, 0)) < 0) { - clLog()->Error(XrdCl::AppMsg, "Cache::Config() can't open configuration file %s", config_filename); + TRACE( Error, "Cache::Config() can't open configuration file " << config_filename); return false; } @@ -138,7 +138,7 @@ bool Cache::Config(XrdSysLogger *logger, const char *config_filename, const char } else { - clLog()->Error(XrdCl::AppMsg, "Cache::Config() Unable to create an OSS object"); + TRACE(Error, "Cache::Config() Unable to create an OSS object"); m_output_fs = 0; return false; } @@ -169,7 +169,7 @@ bool Cache::Config(XrdSysLogger *logger, const char *config_filename, const char if (!retval) { retval = false; - clLog()->Error(XrdCl::AppMsg, "Cache::Config() error in parsing"); + TRACE(Error, "Cache::Config() error in parsing"); break; } @@ -183,15 +183,14 @@ bool Cache::Config(XrdSysLogger *logger, const char *config_filename, const char if (m_output_fs->StatVS(&sP, "public", 1) >= 0) { m_configuration.m_diskUsageLWM = static_cast(0.90 * sP.Total + 0.5); m_configuration.m_diskUsageHWM = static_cast(0.95 * sP.Total + 0.5); - clLog()->Debug(XrdCl::AppMsg, "Default disk usage [%lld, %lld]", m_configuration.m_diskUsageLWM, m_configuration.m_diskUsageHWM); } } // get number of available RAM blocks after process configuration if (m_configuration.m_RamAbsAvailable == 0 ) { - m_log.Emsg("Error", "RAM usage not specified. Please set pfc.ram value in configuration file."); - return false; + TRACE(Error, "RAM usage not specified. Please set pfc.ram value in configuration file."); + return false; } m_configuration.m_NRamBuffers = static_cast(m_configuration.m_RamAbsAvailable/ m_configuration.m_bufferSize); @@ -207,12 +206,13 @@ bool Cache::Config(XrdSysLogger *logger, const char *config_filename, const char loff = snprintf(buff, sizeof(buff), "Config effective %s pfc configuration:\n" " pfc.blocksize %lld\n" " pfc.prefetch %ld\n" - " pfc.ram %.fg", + " pfc.ram %.fg" + " pfc.trace %d", config_filename, m_configuration.m_bufferSize, m_configuration.m_prefetch_max_blocks, // AMT not sure what parsing should be - rg); - + rg, + m_trace->What); if (m_configuration.m_hdfsmode) { diff --git a/src/XrdFileCache/XrdFileCacheFile.cc b/src/XrdFileCache/XrdFileCacheFile.cc index 885ccd6f925..273896615aa 100644 --- a/src/XrdFileCache/XrdFileCacheFile.cc +++ b/src/XrdFileCache/XrdFileCacheFile.cc @@ -75,7 +75,7 @@ File::File(XrdOucCacheIO2 *inputIO, std::string& disk_file_path, long long iOffs m_input(inputIO), m_output(NULL), m_infoFile(NULL), -m_cfi(Cache::GetInstance().RefConfiguration().m_bufferSize, Cache::GetInstance().RefConfiguration().m_prefetch_max_blocks > 0), +m_cfi(Cache::GetInstance().GetTrace(), Cache::GetInstance().RefConfiguration().m_bufferSize, Cache::GetInstance().RefConfiguration().m_prefetch_max_blocks > 0), m_temp_filename(disk_file_path), m_offset(iOffset), m_fileSize(iFileSize), @@ -92,24 +92,19 @@ m_prefetchScore(1), m_prefetchCurrentCnt(0), m_traceID("File") { - clLog()->Debug(XrdCl::AppMsg, "File::File() %s", m_temp_filename.c_str()); - if (!Open()) { - clLog()->Error(XrdCl::AppMsg, "File::File() Open failed %s !!!", m_temp_filename.c_str()); - } + Open(); } void File::BlockRemovedFromWriteQ(Block* b) { m_downloadCond.Lock(); dec_ref_count(b); - clLog()->Dump(XrdCl::AppMsg, "File::BlockRemovedFromWriteQ() check write queues %p %d...%s", (void*)b, b->m_offset/m_cfi.GetBufferSize(), lPath()); + TRACEF(Dump, "File::BlockRemovedFromWriteQ() check write queues block = " << (void*)b << " idx= " << b->m_offset/m_cfi.GetBufferSize()); m_downloadCond.UnLock(); } File::~File() { - clLog()->Debug(XrdCl::AppMsg, "File::~File() enter %p %s", (void*)this, lPath()); - m_syncStatusMutex.Lock(); bool needs_sync = ! m_writes_during_sync.empty(); m_syncStatusMutex.UnLock(); @@ -122,7 +117,6 @@ File::~File() AppendIOStatToFileInfo(); m_infoFile->Fsync(); - clLog()->Info(XrdCl::AppMsg, "File::~File close data file %p",(void*)this , lPath()); if (m_output) { m_output->Close(); @@ -131,20 +125,20 @@ File::~File() } if (m_infoFile) { - clLog()->Info(XrdCl::AppMsg, "File::~File close info file"); m_infoFile->Close(); delete m_infoFile; m_infoFile = NULL; } // print just for curiosity - clLog()->Debug(XrdCl::AppMsg, "File::~File() ended, prefetch score ...%d/%d=%.2f", m_prefetchHitCnt, m_prefetchReadCnt, m_prefetchScore); + TRACEF(Debug, "File::~File() ended, prefetch score = " << m_prefetchScore); } bool File::InitiateClose() { // Retruns true if delay is needed - clLog()->Debug(XrdCl::AppMsg, "File::Initiate close start %s", lPath()); + + TRACEF(Debug, "File::Initiate close start"); m_stateCond.Lock(); if (!m_stopping) { @@ -161,19 +155,23 @@ bool File::InitiateClose() if (isPrefetching == false) { m_downloadCond.Lock(); - /* + + /* + // dump print for (BlockMap_i it = m_block_map.begin(); it != m_block_map.end(); ++it) { Block* b = it->second; - clLog()->Debug(XrdCl::AppMsg, "File::InitiateClose() block idx=%d p=%d rcnt=%d dwnd=%d %s", - b->m_offset/m_cfi.GetBufferSize(), b->m_prefetch, b->m_refcnt, b->m_downloaded, lPath()); + TRACEF(Dump, "File::InitiateClose() block idx = " << b->m_offset/m_cfi.GetBufferSize() << " prefetch = " << b->preferch << " refcnt " << b->refcnt); + } */ + // remove failed blocks BlockMap_i itr = m_block_map.begin(); while (itr != m_block_map.end()) { if (itr->second->is_failed() && itr->second->m_refcnt == 1) { BlockMap_i toErase = itr; ++itr; + TRACEF(Debug, "Remove failed block " << itr->second->m_offset/m_cfi.GetBufferSize()); free_block(toErase->second); } else { @@ -207,7 +205,7 @@ bool File::InitiateClose() bool File::Open() { - clLog()->Dump(XrdCl::AppMsg, "File::Open() open file for disk cache %s", m_temp_filename.c_str()); + TRACEF(Dump, "File::Open() open file for disk cache "); XrdOss &m_output_fs = *Cache::GetInstance().GetOss(); // Create the data file itself. @@ -219,16 +217,15 @@ bool File::Open() int res = m_output->Open(m_temp_filename.c_str(), O_RDWR, 0600, myEnv); if (res < 0) { - clLog()->Error(XrdCl::AppMsg, "File::Open() can't get data-FD for %s %s", m_temp_filename.c_str(), m_temp_filename.c_str()); + TRACEF(Error, "File::Open() can't open data file"); delete m_output; m_output = 0; - return false; } } else { - clLog()->Error(XrdCl::AppMsg, "File::Open() can't get data holder "); + TRACEF(Error, "File::Open() can't get file handle"); return false; } @@ -241,7 +238,7 @@ bool File::Open() int res = m_infoFile->Open(ifn.c_str(), O_RDWR, 0600, myEnv); if (res < 0) { - clLog()->Error(XrdCl::AppMsg, "File::Open() can't get info-FD %s %s", ifn.c_str(), m_temp_filename.c_str()); + TRACEF(Error, "File::Open() can't open info file"); delete m_infoFile; m_infoFile = 0; return false; @@ -256,17 +253,16 @@ bool File::Open() { m_fileSize = m_fileSize; int ss = (m_fileSize - 1)/m_cfi.GetBufferSize() + 1; - clLog()->Info(XrdCl::AppMsg, "Creating new file info with size %lld. Reserve space for %d blocks %s", m_fileSize, ss, m_temp_filename.c_str()); + TRACEF(Debug, "Creating new file info, data size = " << m_fileSize << " num blocks = " << ss); m_cfi.SetFileSize(m_fileSize); m_cfi.WriteHeader(m_infoFile); m_infoFile->Fsync(); } else { - clLog()->Debug(XrdCl::AppMsg, "Info file read from disk: %s", m_temp_filename.c_str()); + TRACEF(Debug, "Successfully opened existing info file"); } - cache()->RegisterPrefetchFile(this); return true; } @@ -321,7 +317,6 @@ Block* File::RequestBlock(int i, bool prefetch) // // Reference count is 0 so increase it in calling function if you want to // catch the block while still in memory. - clLog()->Debug(XrdCl::AppMsg, "RequestBlock() %d pOn=(%d)", i, prefetch); const long long BS = m_cfi.GetBufferSize(); @@ -332,10 +327,10 @@ Block* File::RequestBlock(int i, bool prefetch) Block *b = new Block(this, off, this_bs, prefetch); // should block be reused to avoid recreation + TRACEF(Dump, "File::RequestBlock() " << i << "prefetch" << prefetch << "address " << (void*)b); BlockResponseHandler* oucCB = new BlockResponseHandler(b); m_input->Read(*oucCB, (char*)b->get_buff(), off, (int)this_bs); - clLog()->Dump(XrdCl::AppMsg, "File::RequestBlock() this = %p, b=%p, this idx=%d pOn=(%d) %s", (void*)this, (void*)b, i, prefetch, lPath()); m_block_map[i] = b; if (m_prefetchState == kOn && m_block_map.size() > Cache::GetInstance().RefConfiguration().m_prefetch_max_blocks) @@ -367,7 +362,7 @@ int File::RequestBlocksDirect(DirectResponseHandler *handler, IntList_t& blocks, overlap(*ii, BS, req_off, req_size, off, blk_off, size); m_input->Read( *handler, req_buf + off, *ii * BS + blk_off, size); - clLog()->Dump(XrdCl::AppMsg, "RequestBlockDirect success %d %ld %s", *ii, size, lPath()); + TRACEF(Dump, "RequestBlockDirect success, idx = " << *ii << " size = " << size); total += size; } @@ -380,8 +375,7 @@ int File::RequestBlocksDirect(DirectResponseHandler *handler, IntList_t& blocks, int File::ReadBlocksFromDisk(std::list& blocks, char* req_buf, long long req_off, long long req_size) { - - clLog()->Dump(XrdCl::AppMsg, "File::ReadBlocksFromDisk %ld %s", blocks.size(), lPath()); + TRACEF(Dump, "File::ReadBlocksFromDisk " << blocks.size()); const long long BS = m_cfi.GetBufferSize(); long long total = 0; @@ -398,17 +392,17 @@ int File::ReadBlocksFromDisk(std::list& blocks, overlap(*ii, BS, req_off, req_size, off, blk_off, size); long long rs = m_output->Read(req_buf + off, *ii * BS + blk_off -m_offset, size); - clLog()->Dump(XrdCl::AppMsg, "File::ReadBlocksFromDisk block %d size %d %s", *ii, size, lPath()); + TRACEF(Dump, "File::ReadBlocksFromDisk block idx = " << *ii << " size= " << size); if (rs < 0) { - clLog()->Error(XrdCl::AppMsg, "File::ReadBlocksFromDisk neg retval %ld (%ld@%d) %s", rs, *ii * BS + blk_off, lPath()); + TRACEF(Error, "File::ReadBlocksFromDisk neg retval = " << rs << " idx = " << *ii ); return rs; } // AMT I think we should exit in this case too if (rs !=size) { - clLog()->Error(XrdCl::AppMsg, "File::ReadBlocksFromDisk incomplete %ld (%ld@%d) %s", rs, *ii * BS + blk_off, lPath()); + TRACEF(Error, "File::ReadBlocksFromDisk incomplete size = " << rs << " idx = " << *ii); return -1; } @@ -449,7 +443,7 @@ int File::Read(char* iUserBuff, long long iUserOff, int iUserSize) for (int block_idx = idx_first; block_idx <= idx_last; ++block_idx) { - clLog()->Dump(XrdCl::AppMsg, "--- File::Read() idx %d %s \n", block_idx, lPath()); + TRACEF(Dump, "File::Read() idx " << block_idx); BlockMap_i bi = m_block_map.find(block_idx); // In RAM or incoming? @@ -459,14 +453,14 @@ int File::Read(char* iUserBuff, long long iUserOff, int iUserSize) // XXXX Or just push it and handle errors in one place later? inc_ref_count(bi->second); - clLog()->Dump(XrdCl::AppMsg, "File::Read() u=%p inc_ref_count for existing block %p %d %s", (void*)iUserBuff, (void*)bi->second, block_idx, lPath()); + TRACEF(Dump, "File::Read() " << iUserBuff << "inc_ref_count for existing block << " << bi->second << " idx = " << block_idx); blks_to_process.push_front(bi->second); m_stats.m_BytesRam++; // AMT what if block fails } // On disk? else if (m_cfi.TestBit(offsetIdx(block_idx))) { - clLog()->Dump(XrdCl::AppMsg, "File::Read() u=%p read from disk %d %s", (void*)iUserBuff, block_idx, lPath()); + TRACEF(Dump, "File::Read() read from disk " << (void*)iUserBuff << " idx = " << block_idx); blks_on_disk.push_back(block_idx); m_stats.m_BytesDisk++; } @@ -476,7 +470,7 @@ int File::Read(char* iUserBuff, long long iUserOff, int iUserSize) // Is there room for one more RAM Block? if ( cache()->HaveFreeWritingSlots() && cache()->RequestRAMBlock()) { - clLog()->Dump(XrdCl::AppMsg, "File::Read() u=%p inc_ref_count new %d %s", (void*)iUserBuff, block_idx, lPath()); + TRACEF(Dump, "File::Read() inc_ref_count new " << (void*)iUserBuff << " idx = " << block_idx); Block *b = RequestBlock(block_idx, false); // assert(b); if (!b) { @@ -490,7 +484,7 @@ int File::Read(char* iUserBuff, long long iUserOff, int iUserSize) // Nope ... read this directly without caching. else { - clLog()->Debug(XrdCl::AppMsg, "File::Read() direct block %d %s", block_idx, lPath()); + TRACEF(Dump, "File::Read() direct block " << block_idx); blks_direct.push_back(block_idx); m_stats.m_BytesMissed++; } @@ -525,13 +519,13 @@ int File::Read(char* iUserBuff, long long iUserOff, int iUserSize) delete direct_handler; return -1; // AMT ??? } - clLog()->Dump(XrdCl::AppMsg, "File::Read() direct read %d. %s", direct_size, lPath()); + TRACEF(Dump, "File::Read() direct read finished, size = " << direct_size); } // Second, read blocks from disk. if ((!blks_on_disk.empty()) && (bytes_read >= 0)) { int rc = ReadBlocksFromDisk(blks_on_disk, iUserBuff, iUserOff, iUserSize); - clLog()->Dump(XrdCl::AppMsg, "File::Read() u=%p, from disk %d. %s", (void*)iUserBuff, rc, lPath()); + TRACEF(Dump, "File::Read() " << (void*)iUserBuff <<" from disk finished size = " << rc); if (rc >= 0) { bytes_read += rc; @@ -539,7 +533,7 @@ int File::Read(char* iUserBuff, long long iUserOff, int iUserSize) else { bytes_read = rc; - clLog()->Error(XrdCl::AppMsg, "File::Read() failed to read from disk. %s", lPath()); + TRACEF(Error, "File::Read() failed read from disk"); // AMT commented line below should not be an immediate return, can have block refcount increased and map increased // return rc; } @@ -556,10 +550,9 @@ int File::Read(char* iUserBuff, long long iUserOff, int iUserSize) BlockList_i bi = blks_to_process.begin(); while (bi != blks_to_process.end()) { - // clLog()->Dump(XrdCl::AppMsg, "File::Read() searcing for block %p finished", (void*)(*bi)); if ((*bi)->is_finished()) { - clLog()->Dump(XrdCl::AppMsg, "File::Read() found finished block %p %s", (void*)(*bi), lPath()); + TRACEF(Dump, "File::Read() requested block downloaded " << (void*)(*bi)); finished.push_back(*bi); BlockList_i bj = bi++; blks_to_process.erase(bj); @@ -572,18 +565,16 @@ int File::Read(char* iUserBuff, long long iUserOff, int iUserSize) if (finished.empty()) { - - clLog()->Dump(XrdCl::AppMsg, "File::Read() wait block begin %s", lPath()); + TRACEF(Dump, "File::Read() wait block begin" ); m_downloadCond.Wait(); - clLog()->Dump(XrdCl::AppMsg, "File::Read() wait block end %s", lPath()); + TRACEF(Dump, "File::Read() wait block end"); continue; } } - clLog()->Dump(XrdCl::AppMsg, "File::Read() bytes read before processing blocks %d %s\n", bytes_read, lPath()); BlockList_i bi = finished.begin(); while (bi != finished.end()) @@ -597,7 +588,7 @@ int File::Read(char* iUserBuff, long long iUserOff, int iUserSize) // clLog()->Dump(XrdCl::AppMsg, "File::Read() Block finished ok."); overlap((*bi)->m_offset/BS, BS, iUserOff, iUserSize, user_off, off_in_block, size_to_copy); - clLog()->Dump(XrdCl::AppMsg, "File::Read() u=%p, from finished block %d , size %d end %s", (void*)iUserBuff, (*bi)->m_offset/BS, size_to_copy, lPath()); + TRACEF(Dump, "File::Read() ub=" << (void*)iUserBuff << " from finished block " << (*bi)->m_offset/BS << " size " << size_to_copy); memcpy(&iUserBuff[user_off], &((*bi)->m_buff[off_in_block]), size_to_copy); bytes_read += size_to_copy; @@ -605,7 +596,7 @@ int File::Read(char* iUserBuff, long long iUserOff, int iUserSize) } else // it has failed ... krap up. { - clLog()->Error(XrdCl::AppMsg, "File::Read() Block finished with error %s.", lPath()); + TRACEF(Error, "File::Read(), block "<< (*bi)->m_offset/BS << "finished with error "); bytes_read = -1; errno = (*bi)->m_errno; break; @@ -617,12 +608,10 @@ int File::Read(char* iUserBuff, long long iUserOff, int iUserSize) finished.clear(); } - clLog()->Dump(XrdCl::AppMsg, "File::Read() bytes read after processing blocks %d %s\n", bytes_read, lPath()); - // Fourth, make sure all direct requests have arrived if ((direct_handler != 0) && (bytes_read >= 0 )) { - clLog()->Debug(XrdCl::AppMsg, "File::Read() waiting for direct requests %s.", lPath()); + TRACEF(Dump, "File::Read() waiting for direct requests "); XrdSysCondVarHelper _lck(direct_handler->m_cond); if (direct_handler->m_to_wait > 0) @@ -655,7 +644,7 @@ int File::Read(char* iUserBuff, long long iUserOff, int iUserSize) for (BlockList_i bi = blks_processed.begin(); bi != blks_processed.end(); ++bi) { - clLog()->Dump(XrdCl::AppMsg, "File::Read() dec_ref_count b=%p, %d %s", (void*)(*bi), ((*bi)->m_offset/BufferSize()), lPath()); + TRACEF(Dump, "File::Read() dec_ref_count " << (void*)(*bi) << " idx = " << (int)((*bi)->m_offset/BufferSize())); dec_ref_count(*bi); // XXXX stamp block } @@ -686,18 +675,17 @@ void File::WriteBlockToDisk(Block* b) if (buffer_remaining) { - clLog()->Warning(XrdCl::AppMsg, "File::WriteToDisk() reattempt[%d] writing missing %ld for block %d %s", - cnt, buffer_remaining, b->m_offset, lPath()); + TRACEF(Warning, "File::WriteToDisk() reattempt " << cnt << " writing missing " << buffer_remaining << " for block offset " << b->m_offset); } if (cnt > PREFETCH_MAX_ATTEMPTS) { - clLog()->Error(XrdCl::AppMsg, "File::WriteToDisk() write failed too manny attempts %s", lPath()); + TRACEF(Error, "File::WriteToDisk() write block with off = " << b->m_offset <<" failed too manny attempts "); return; } } // set bit fetched - clLog()->Dump(XrdCl::AppMsg, "File::WriteToDisk() success set bit for block [%ld] size [%d] %s", b->m_offset, size, lPath()); + TRACEF(Dump, "File::WriteToDisk() success set bit for block " << b->m_offset << " size " << size); int pfIdx = (b->m_offset - m_offset)/m_cfi.GetBufferSize(); m_downloadCond.Lock(); @@ -744,7 +732,7 @@ void File::WriteBlockToDisk(Block* b) void File::Sync() { - clLog()->Dump(XrdCl::AppMsg, "File::Sync %s", lPath()); + TRACEF( Dump, "File::Sync()"); m_output->Fsync(); m_cfi.WriteHeader(m_infoFile); int written_while_in_sync; @@ -758,7 +746,7 @@ void File::Sync() m_writes_during_sync.clear(); m_in_sync = false; } - clLog()->Dump(XrdCl::AppMsg, "File::Sync %d blocks written during sync.", written_while_in_sync); + TRACEF(Dump, "File::Sync() "<< written_while_in_sync << " blocks written during sync."); m_infoFile->Fsync(); } @@ -768,7 +756,7 @@ void File::inc_ref_count(Block* b) { // Method always called under lock b->m_refcnt++; - clLog()->Dump(XrdCl::AppMsg, "File::inc_ref_count b=%p, %d %s ",(void*)b, b->m_refcnt, lPath()); + TRACEF(Dump, "File::inc_ref_count " << b << " refcnt " << b->m_refcnt); } //______________________________________________________________________________ @@ -788,12 +776,13 @@ void File::dec_ref_count(Block* b) void File::free_block(Block* b) { int i = b->m_offset/BufferSize(); - clLog()->Dump(XrdCl::AppMsg, "File::free_block block (%p) %d %s ", (void*)b, i, lPath()); + TRACEF(Dump, "File::free_block block " << b << " idx = " << i); delete m_block_map[i]; size_t ret = m_block_map.erase(i); if (ret != 1) { - clLog()->Error(XrdCl::AppMsg, "File::OnBlockZeroRefCount did not erase %d from map.", i); + // assert might be a better option than a warning + TRACEF(Warning, "File::OnBlockZeroRefCount did not erase " << i << " from map"); } else { @@ -814,13 +803,13 @@ void File::ProcessBlockResponse(Block* b, int res) m_downloadCond.Lock(); - clLog()->Debug(XrdCl::AppMsg, "File::ProcessBlockResponse %p, %d %s",(void*)b,(int)(b->m_offset/BufferSize()), lPath()); + TRACEF(Dump, "File::ProcessBlockResponse " << (void*)b << " " << b->m_offset/BufferSize()); if (res >= 0) { b->m_downloaded = true; - clLog()->Debug(XrdCl::AppMsg, "File::ProcessBlockResponse %d finished %d %s",(int)(b->m_offset/BufferSize()), b->is_finished(), lPath()); + TRACEF(Dump, "File::ProcessBlockResponse " << (int)(b->m_offset/BufferSize()) << " finished " << b->is_finished()); if (!m_stopping) { // AMT theoretically this should be under state lock, but then are double locks - clLog()->Debug(XrdCl::AppMsg, "File::ProcessBlockResponse inc_ref_count %d %s\n", (int)(b->m_offset/BufferSize()), lPath()); + TRACEF(Dump, "File::ProcessBlockResponse inc_ref_count " << (int)(b->m_offset/BufferSize())); inc_ref_count(b); cache()->AddWriteTask(b, true); } @@ -834,7 +823,7 @@ void File::ProcessBlockResponse(Block* b, int res) { // AMT how long to keep? // when to retry? - clLog()->Error(XrdCl::AppMsg, "File::ProcessBlockResponse block %p %d error=%d, %s",(void*)b,(int)(b->m_offset/BufferSize()), res, lPath()); + TRACEF(Error, "File::ProcessBlockResponse block " << b << " " << (int)(b->m_offset/BufferSize()) << " error=" << res); // XrdPosixMap::Result(*status); // AMT could notfiy global cache we dont need RAM for that block b->set_error_and_free(errno); @@ -882,7 +871,7 @@ void File::AppendIOStatToFileInfo() } else { - clLog()->Warning(XrdCl::AppMsg, "File::AppendIOStatToFileInfo() info file not opened %s", lPath()); + TRACEF(Warning, "File::AppendIOStatToFileInfo() info file not opened"); } } @@ -891,7 +880,7 @@ void File::Prefetch() { if (m_prefetchState == kOn) { - // clLog()->Dump(XrdCl::AppMsg, "File::Prefetch enter to check download status \n"); + TRACEF(Dump, "File::Prefetch enter to check download status"); XrdSysCondVarHelper _lck(m_downloadCond); // clLog()->Dump(XrdCl::AppMsg, "File::Prefetch enter to check download status BEGIN %s \n", lPath()); @@ -905,7 +894,7 @@ void File::Prefetch() f += m_offset/m_cfi.GetBufferSize(); BlockMap_i bi = m_block_map.find(f); if (bi == m_block_map.end()) { - clLog()->Dump(XrdCl::AppMsg, "File::Prefetch take block %d %s", f, lPath()); + TRACEF(Dump, "File::Prefetch take block " << f); cache()->RequestRAMBlock(); RequestBlock(f, true); m_prefetchReadCnt++; @@ -916,15 +905,13 @@ void File::Prefetch() } } if (!found) { - clLog()->Dump(XrdCl::AppMsg, "File::Prefetch no free blcok found "); + TRACEF(Dump, "File::Prefetch no free block found "); m_cfi.CheckComplete(); - // assert (m_cfi.IsComplete()); // it is possible all missing blocks are in map but downlaoded status is still not complete - clLog()->Dump(XrdCl::AppMsg, "File::Prefetch -- unlikely to happen ... file seem to be complete %s", lPath()); + // assert (m_cfi.IsComplete()); // remove block from map cache()->DeRegisterPrefetchFile(this); } - clLog()->Dump(XrdCl::AppMsg, "File::Prefetch end"); } UnMarkPrefetch(); @@ -974,14 +961,18 @@ void File::UnMarkPrefetch() m_stateCond.UnLock(); } + +XrdOucTrace* File::GetTrace() +{ + return Cache::GetInstance().GetTrace(); +} + //============================================================================== //================== RESPONSE HANDLER ================================== //============================================================================== void BlockResponseHandler::Done(int res) { - XrdCl::DefaultEnv::GetLog()->Dump(XrdCl::AppMsg,"BlockResponseHandler::Done()"); - m_block->m_file->ProcessBlockResponse(m_block, res); delete this; @@ -991,7 +982,6 @@ void BlockResponseHandler::Done(int res) void DirectResponseHandler::Done(int res) { - XrdCl::DefaultEnv::GetLog()->Dump(XrdCl::AppMsg,"DirectResponseHandler::Done()"); XrdSysCondVarHelper _lck(m_cond); --m_to_wait; diff --git a/src/XrdFileCache/XrdFileCacheFile.hh b/src/XrdFileCache/XrdFileCacheFile.hh index 9185ae642fa..116cf737c9f 100644 --- a/src/XrdFileCache/XrdFileCacheFile.hh +++ b/src/XrdFileCache/XrdFileCacheFile.hh @@ -191,7 +191,9 @@ namespace XrdFileCache //! Log path const char* lPath() const; - std::string GetLocalPath(); + std::string GetLocalPath() { return m_temp_filename; } + + XrdOucTrace* GetTrace(); private: bool overlap(int blk, // block to query long long blk_size, // @@ -215,7 +217,6 @@ namespace XrdFileCache int VReadFromDisk(const XrdOucIOVec *readV, int n, ReadVBlockListDisk& blks_on_disk); int VReadProcessBlocks(const XrdOucIOVec *readV, int n, std::vector& blks_to_process, std::vector& blks_rocessed); - long long BufferSize(); void AppendIOStatToFileInfo(); @@ -224,9 +225,6 @@ namespace XrdFileCache void UnMarkPrefetch(); - //! Short log alias. - XrdCl::Log* clLog() const { return XrdCl::DefaultEnv::GetLog(); } - void inc_ref_count(Block*); void dec_ref_count(Block*); void free_block(Block*); diff --git a/src/XrdFileCache/XrdFileCacheIO.hh b/src/XrdFileCache/XrdFileCacheIO.hh index 36007a154ee..3b272788ddc 100644 --- a/src/XrdFileCache/XrdFileCacheIO.hh +++ b/src/XrdFileCache/XrdFileCacheIO.hh @@ -1,10 +1,13 @@ #ifndef __XRDFILECACHE_CACHE_IO_HH__ #define __XRDFILECACHE_CACHE_IO_HH__ +class XrdOucTrace; + #include "XrdFileCache.hh" #include "XrdOuc/XrdOucCache2.hh" #include "XrdCl/XrdClDefaultEnv.hh" + namespace XrdFileCache { //---------------------------------------------------------------------------- @@ -36,9 +39,9 @@ namespace XrdFileCache virtual void RelinquishFile(File*) = 0; - protected: - XrdCl::Log* clLog() const { return XrdCl::DefaultEnv::GetLog(); } + XrdOucTrace* GetTrace() {return m_cache.GetTrace();} + protected: XrdOucCacheIO2 *m_io; //!< original data source XrdOucCacheStats &m_statsGlobal; //!< reference to Cache statistics Cache &m_cache; //!< reference to Cache needed in detach diff --git a/src/XrdFileCache/XrdFileCacheIOEntireFile.cc b/src/XrdFileCache/XrdFileCacheIOEntireFile.cc index c2cf4c6d68f..b2bbea978e8 100644 --- a/src/XrdFileCache/XrdFileCacheIOEntireFile.cc +++ b/src/XrdFileCache/XrdFileCacheIOEntireFile.cc @@ -19,13 +19,13 @@ #include #include -//#include "XrdClient/XrdClientConst.hh" #include "XrdSys/XrdSysError.hh" #include "XrdSfs/XrdSfsInterface.hh" #include "XrdSys/XrdSysPthread.hh" #include "XrdFileCacheIOEntireFile.hh" #include "XrdFileCacheStats.hh" +#include "XrdFileCacheTrace.hh" #include "XrdOuc/XrdOucEnv.hh" @@ -39,8 +39,6 @@ IOEntireFile::IOEntireFile(XrdOucCacheIO2 *io, XrdOucCacheStats &stats, Cache & m_file(0), m_localStat(0) { - clLog()->Info(XrdCl::AppMsg, "IO::IO() [%p] %s", this, m_io->Path()); - XrdCl::URL url(m_io->Path()); std::string fname = Cache::GetInstance().RefConfiguration().m_cache_dir + url.GetPath(); @@ -92,7 +90,7 @@ struct stat* IOEntireFile::getValidLocalStat(const char* path) XrdOucEnv myEnv; int res = infoFile->Open(path, O_RDONLY, 0600, myEnv); if (res >= 0) { - Info info(0); + Info info(m_cache.GetTrace(), 0); if (info.Read(infoFile) > 0) { tmpStat.st_size = info.GetFileSize(); m_localStat = new struct stat; @@ -131,24 +129,16 @@ void IOEntireFile::Read (XrdOucCacheIOCB &iocb, char *buff, long long offs, int int IOEntireFile::Read (char *buff, long long off, int size) { - clLog()->Debug(XrdCl::AppMsg, "IOEntireFile::Read() [%p] %lld@%d %s", this, off, size, m_io->Path()); - - // protect from reads over the file size - // if (off >= m_io->FSize()) - // return 0; + TRACEIO(Dump, "IOEntireFile::Read() "<< this << " off: " << off << " size: " << size ); if (off < 0) { errno = EINVAL; return -1; } - //if (off + size > m_io->FSize()) - // size = m_io->FSize() - off; - ssize_t bytes_read = 0; ssize_t retval = 0; retval = m_file->Read(buff, off, size); - clLog()->Debug(XrdCl::AppMsg, "IOEntireFile::Read() read from File retval = %d %s", retval, m_io->Path()); if (retval >= 0) { bytes_read += retval; @@ -156,11 +146,11 @@ int IOEntireFile::Read (char *buff, long long off, int size) size -= retval; if (size > 0) - clLog()->Warning(XrdCl::AppMsg, "IOEntireFile::Read() missed %d bytes %s", size, m_io->Path()); + TRACEIO(Warning, "IOEntireFile::Read() bytes missed " << size ); } else { - clLog()->Error(XrdCl::AppMsg, "IOEntireFile::Read(), origin bytes read %d %s", retval, m_io->Path()); + TRACEIO(Warning, "IOEntireFile::Read() pass to origin bytes ret " << retval ); } return (retval < 0) ? retval : bytes_read; @@ -172,8 +162,6 @@ int IOEntireFile::Read (char *buff, long long off, int size) */ int IOEntireFile::ReadV (const XrdOucIOVec *readV, int n) { - clLog()->Warning(XrdCl::AppMsg, "IOEntireFile::ReadV(), get %d requests %s", n, m_io->Path()); - - + TRACE(Dump, "IO::ReadV(), get " << n << " requests, " << m_io->Path()); return m_file->ReadV(readV, n); } diff --git a/src/XrdFileCache/XrdFileCacheIOFileBlock.cc b/src/XrdFileCache/XrdFileCacheIOFileBlock.cc index cdcc139e654..82639a1abea 100644 --- a/src/XrdFileCache/XrdFileCacheIOFileBlock.cc +++ b/src/XrdFileCache/XrdFileCacheIOFileBlock.cc @@ -25,6 +25,7 @@ #include "XrdFileCacheIOFileBlock.hh" #include "XrdFileCache.hh" #include "XrdFileCacheStats.hh" +#include "XrdFileCacheTrace.hh" #include "XrdSys/XrdSysError.hh" #include "XrdSfs/XrdSfsInterface.hh" @@ -43,7 +44,7 @@ IOFileBlock::IOFileBlock(XrdOucCacheIO2 *io, XrdOucCacheStats &statsGlobal, Cach //______________________________________________________________________________ XrdOucCacheIO* IOFileBlock::Detach() { - clLog()->Info(XrdCl::AppMsg, "IOFileBlock::Detach() %s", m_io->Path()); + TRACEIO(Info, "IOFileBlock::Detach() " ); XrdOucCacheIO * io = m_io; @@ -77,7 +78,7 @@ void IOFileBlock::GetBlockSizeFromPath() m_blocksize = atoi(path.substr(pos1).c_str()); } - clLog()->Debug(XrdCl::AppMsg, "FileBlock::GetBlockSizeFromPath(), blocksize = %lld. %s", m_blocksize, m_io->Path()); + TRACEIO(Debug, "FileBlock::GetBlockSizeFromPath(), blocksize = " << m_blocksize ); } } @@ -95,7 +96,7 @@ File* IOFileBlock::newBlockFile(long long off, int blocksize) ss << &offExt[0]; fname = ss.str(); - clLog()->Debug(XrdCl::AppMsg, "FileBlock::FileBlock(), create XrdFileCacheFile. %s", m_io->Path()); + TRACEIO(Debug, "FileBlock::FileBlock(), create XrdFileCacheFile "); File* file; if (!(file = Cache::GetInstance().GetFileWithLocalPath(fname, this))) @@ -159,7 +160,7 @@ int IOFileBlock::Read (char *buff, long long off, int size) int idx_first = off0/m_blocksize; int idx_last = (off0+size-1)/m_blocksize; int bytes_read = 0; - clLog()->Debug(XrdCl::AppMsg, "IOFileBlock::Read() %lld@%d block range [%d-%d] \n %s", off, size, idx_first, idx_last, m_io->Path()); + TRACEIO(Debug, "IOFileBlock::Read() "<< off << "@" << size << " block range ["<< idx_first << ", " << idx_last << "]"); for (int blockIdx = idx_first; blockIdx <= idx_last; ++blockIdx ) { @@ -179,7 +180,7 @@ int IOFileBlock::Read (char *buff, long long off, int size) if (blockIdx == lastIOFileBlock ) { pbs = m_io->FSize() - blockIdx*m_blocksize; - clLog()->Debug(XrdCl::AppMsg, "IOFileBlock::Read() last block, change output file size to %lld \n %s", pbs, m_io->Path()); + // TRACEIO(Dump, "IOFileBlock::Read() last block, change output file size to " << pbs); } fb = newBlockFile(blockIdx*m_blocksize, pbs); @@ -194,12 +195,12 @@ int IOFileBlock::Read (char *buff, long long off, int size) if (blockIdx == idx_first) { readBlockSize = (blockIdx + 1) *m_blocksize - off0; - clLog()->Debug(XrdCl::AppMsg, "Read partially till the end of the block %s", m_io->Path()); + TRACEIO(Dump, "Read partially till the end of the block"); } else if (blockIdx == idx_last) { readBlockSize = (off0+size) - blockIdx*m_blocksize; - clLog()->Debug(XrdCl::AppMsg, "Read partially from beginning of block %s", m_io->Path()); + TRACEIO(Dump, "Read partially till the end of the block %s"); } else { @@ -208,14 +209,14 @@ int IOFileBlock::Read (char *buff, long long off, int size) } assert(readBlockSize); - clLog()->Info(XrdCl::AppMsg, "IOFileBlock::Read() block[%d] read-block-size[%d], offset[%lld] %s", blockIdx, readBlockSize, off, m_io->Path()); + TRACEIO(Debug, "IOFileBlock::Read() block[ " << blockIdx << "] read-block-size[" << readBlockSize << "], offset[" << readBlockSize << "] off = " << off ); long long min = blockIdx*m_blocksize; if ( off < min) { assert(0); } assert(off+readBlockSize <= (min + m_blocksize)); int retvalBlock = fb->Read(buff, off, readBlockSize); - clLog()->Debug(XrdCl::AppMsg, "IOFileBlock::Read() Block read returned %d %s", retvalBlock , m_io->Path()); + TRACEIO(Dump, "IOFileBlock::Read() Block read returned " << retvalBlock); if (retvalBlock == readBlockSize ) { bytes_read += retvalBlock; @@ -223,12 +224,12 @@ int IOFileBlock::Read (char *buff, long long off, int size) off += retvalBlock; } else if (retvalBlock > 0) { - clLog()->Warning(XrdCl::AppMsg, "IOFileBlock::Read() incomplete read, missing bytes %d %s", readBlockSize-retvalBlock, m_io->Path()); + TRACEIO(Warning, "IOFileBlock::Read() incomplete read, missing bytes " << readBlockSize-retvalBlock); return bytes_read + retvalBlock; } else { - clLog()->Error(XrdCl::AppMsg, "IOFileBlock::Read() read error, retval %d %s", retvalBlock, m_io->Path()); + TRACEIO(Error, "IOFileBlock::Read() read error, retval" << retvalBlock); return retvalBlock; } } diff --git a/src/XrdFileCache/XrdFileCacheInfo.cc b/src/XrdFileCache/XrdFileCacheInfo.cc index d4f343724b8..40c0b1f7461 100644 --- a/src/XrdFileCache/XrdFileCacheInfo.cc +++ b/src/XrdFileCache/XrdFileCacheInfo.cc @@ -25,18 +25,23 @@ #include "XrdOss/XrdOss.hh" #include "XrdOuc/XrdOucSxeq.hh" +#include "XrdOuc/XrdOucTrace.hh" #include "XrdCl/XrdClLog.hh" #include "XrdCl/XrdClConstants.hh" #include "XrdFileCacheInfo.hh" #include "XrdFileCache.hh" +#include "XrdFileCacheStats.hh" +#include "XrdFileCacheTrace.hh" const char* XrdFileCache::Info::m_infoExtension = ".cinfo"; +const char* XrdFileCache::Info::m_traceID = "cinfo"; #define BIT(n) (1ULL << (n)) using namespace XrdFileCache; -Info::Info(long long iBufferSize, bool prefetchBuffer) : +Info::Info(XrdOucTrace* trace, long long iBufferSize, bool prefetchBuffer) : + m_trace(trace), m_version(1), m_bufferSize(iBufferSize), m_hasPrefetchBuffer(prefetchBuffer), @@ -89,7 +94,7 @@ int Info::Read(XrdOssDF* fp) int version; off += fp->Read(&version, off, sizeof(int)); if (version != m_version) { - clLog()->Dump(XrdCl::AppMsg, "Info:::Read(), incomatible file version"); + TRACE(Error, "Info:::Read(), incomatible file version"); return 0; } @@ -108,7 +113,7 @@ int Info::Read(XrdOssDF* fp) off += fp->Read(&m_accessCnt, off, sizeof(int)); - clLog()->Dump(XrdCl::AppMsg, "Info:::Read() complete %d access_cnt %d", m_complete, m_accessCnt); + TRACE(Dump, "Info:::Read() complete "<< m_complete << " access_cnt " << m_accessCnt); if (m_hasPrefetchBuffer) { @@ -132,7 +137,7 @@ int Info::GetHeaderSize() const void Info::WriteHeader(XrdOssDF* fp) { int flr = XrdOucSxeq::Serialize(fp->getFD(), XrdOucSxeq::noWait); - if (flr) clLog()->Error(XrdCl::AppMsg, "WriteHeader() lock failed %s \n", strerror(errno)); + if (flr) TRACE(Error, "Info::WriteHeader() lock failed " << strerror(errno)); long long off = 0; off += fp->Write(&m_version, off, sizeof(int)); @@ -142,7 +147,7 @@ void Info::WriteHeader(XrdOssDF* fp) off += fp->Write(m_buff_write_called, off, GetSizeInBytes()); flr = XrdOucSxeq::Release(fp->getFD()); - if (flr) clLog()->Error(XrdCl::AppMsg, "WriteHeader() un-lock failed \n"); + if (flr) TRACE(Error, "Info::WriteHeader() un-lock failed"); assert (off == GetHeaderSize()); } @@ -150,10 +155,13 @@ void Info::WriteHeader(XrdOssDF* fp) //______________________________________________________________________________ void Info::AppendIOStat(AStat& as, XrdOssDF* fp) { - clLog()->Info(XrdCl::AppMsg, "Info:::AppendIOStat()"); + TRACE(Dump, "Info:::AppendIOStat()"); int flr = XrdOucSxeq::Serialize(fp->getFD(), 0); - if (flr) clLog()->Error(XrdCl::AppMsg, "AppendIOStat() lock failed \n"); + if (flr) { + TRACE(Error, "Info::AppendIOStat() lock failed"); + return; + } m_accessCnt++; long long off = GetHeaderSize(); @@ -162,7 +170,10 @@ void Info::AppendIOStat(AStat& as, XrdOssDF* fp) long long ws = fp->Write(&as, off, sizeof(AStat)); flr = XrdOucSxeq::Release(fp->getFD()); - if (flr) clLog()->Error(XrdCl::AppMsg, "AppenIOStat() un-lock failed \n"); + if (flr) { + TRACE(Error, "Info::AppenIOStat() un-lock failed"); + return; + } if ( ws != sizeof(AStat)) { assert(0); } } @@ -173,7 +184,10 @@ bool Info::GetLatestDetachTime(time_t& t, XrdOssDF* fp) const bool res = false; int flr = XrdOucSxeq::Serialize(fp->getFD(), XrdOucSxeq::Share); - if (flr) clLog()->Error(XrdCl::AppMsg, "Info::GetLatestAttachTime() lock failed \n"); + if (flr) { + TRACE(Error, "Info::GetLatestAttachTime() lock failed"); + return false; + } if (m_accessCnt) { AStat stat; @@ -186,13 +200,14 @@ bool Info::GetLatestDetachTime(time_t& t, XrdOssDF* fp) const } else { - clLog()->Error(XrdCl::AppMsg, " Info::GetLatestAttachTime() can't get latest access stat. read bytes = %d", res); + TRACE(Error, " Info::GetLatestAttachTime() can't get latest access stat "); + return false; } } flr = XrdOucSxeq::Release(fp->getFD()); - if (flr) clLog()->Error(XrdCl::AppMsg, "Info::GetLatestAttachTime() lock failed \n"); + if (flr) TRACE(Error, "Info::GetLatestAttachTime() lock failed"); return res; } diff --git a/src/XrdFileCache/XrdFileCacheInfo.hh b/src/XrdFileCache/XrdFileCacheInfo.hh index ea7b6fc1c78..ce114205885 100644 --- a/src/XrdFileCache/XrdFileCacheInfo.hh +++ b/src/XrdFileCache/XrdFileCacheInfo.hh @@ -22,8 +22,9 @@ #include #include +class XrdOucTrace; + #include "XrdSys/XrdSysPthread.hh" -#include "XrdCl/XrdClLog.hh" #include "XrdCl/XrdClConstants.hh" #include "XrdCl/XrdClDefaultEnv.hh" @@ -59,7 +60,7 @@ namespace XrdFileCache //------------------------------------------------------------------------ //! Constructor. //------------------------------------------------------------------------ - Info(long long bufferSize, bool prefetchBuffer = false); + Info(XrdOucTrace* trace, long long bufferSize, bool prefetchBuffer = false); //------------------------------------------------------------------------ //! Destructor. @@ -190,14 +191,12 @@ namespace XrdFileCache const static char* m_infoExtension; + const static char* m_traceID; + XrdOucTrace* GetTrace() const {return m_trace;} protected: - XrdCl::Log* clLog() const { return XrdCl::DefaultEnv::GetLog(); } - - //--------------------------------------------------------------------- - //! Cache statistics and time of access. - //--------------------------------------------------------------------- + XrdOucTrace* m_trace; int m_version; //!< info version long long m_bufferSize; //!< prefetch buffer size @@ -208,7 +207,7 @@ namespace XrdFileCache unsigned char *m_buff_write_called; //!< disk written state vector unsigned char *m_buff_prefetch; //!< prefetch state vector int m_accessCnt; //!< number of written AStat structs - bool m_complete; //!< cached + bool m_complete; //!< cached }; inline bool Info::TestBit(int i) const diff --git a/src/XrdFileCache/XrdFileCachePrint.cc b/src/XrdFileCache/XrdFileCachePrint.cc index b86bbce8e5d..8e6d922590a 100644 --- a/src/XrdFileCache/XrdFileCachePrint.cc +++ b/src/XrdFileCache/XrdFileCachePrint.cc @@ -23,6 +23,7 @@ #include "XrdOuc/XrdOucEnv.hh" #include "XrdOuc/XrdOucStream.hh" #include "XrdOuc/XrdOucArgs.hh" +#include "XrdOuc/XrdOucTrace.hh" #include "XrdOfs/XrdOfsConfigPI.hh" #include "XrdSys/XrdSysLogger.hh" #include "XrdFileCacheInfo.hh" @@ -57,7 +58,11 @@ void Print::printFile(const std::string& path) printf("printing %s ...\n", path.c_str()); XrdOssDF* fh = m_oss->newFile(m_ossUser); fh->Open((path).c_str(),O_RDONLY, 0600, m_env); - Info cfi(0); + + XrdSysLogger log; + XrdSysError err(&log); + XrdOucTrace tr(&err); tr.What = 1; + Info cfi(&tr, 0); long long off = cfi.Read(fh); std::vector statv; diff --git a/src/XrdFileCache/XrdFileCachePurge.cc b/src/XrdFileCache/XrdFileCachePurge.cc index 19ed5a3dd3d..f6ed4d19fdc 100644 --- a/src/XrdFileCache/XrdFileCachePurge.cc +++ b/src/XrdFileCache/XrdFileCachePurge.cc @@ -1,9 +1,11 @@ #include "XrdFileCache.hh" +#include "XrdFileCacheTrace.hh" using namespace XrdFileCache; #include #include "XrdOuc/XrdOucEnv.hh" +#include "XrdOuc/XrdOucTrace.hh" namespace { @@ -48,6 +50,11 @@ namespace long long nByteReq; long long nByteAccum; }; + +XrdOucTrace* GetTrace() +{ + // needed for logging macros + return Cache::GetInstance().GetTrace(); } void FillFileMapRecurse( XrdOssDF* iOssDF, const std::string& path, FPurgeState& purgeState) @@ -56,8 +63,8 @@ void FillFileMapRecurse( XrdOssDF* iOssDF, const std::string& path, FPurgeState& XrdOucEnv env; int rdr; const size_t InfoExtLen = strlen(XrdFileCache::Info::m_infoExtension); // cached var - XrdCl::Log *log = XrdCl::DefaultEnv::GetLog(); + static const char* m_traceID = "Purge"; Cache& factory = Cache::GetInstance(); while ((rdr = iOssDF->Readdir(&buff[0], 256)) >= 0) { @@ -80,19 +87,19 @@ void FillFileMapRecurse( XrdOssDF* iOssDF, const std::string& path, FPurgeState& // XXXX MT - shouldn't we also check if it is currently opened? fh->Open(np.c_str(), O_RDONLY, 0600, env); - Info cinfo(factory.RefConfiguration().m_bufferSize); + Info cinfo(Cache::GetInstance().GetTrace(), factory.RefConfiguration().m_bufferSize); time_t accessTime; cinfo.Read(fh); if (cinfo.GetLatestDetachTime(accessTime, fh)) { - log->Debug(XrdCl::AppMsg, "FillFileMapRecurse() checking %s accessTime %d ", buff, (int)accessTime); + TRACE(Dump, "FillFileMapRecurse() checking " << buff << " accessTime " << accessTime); purgeState.checkFile(accessTime, np.c_str(), cinfo.GetNDownloadedBytes()); } else { // cinfo file does not contain any known accesses, use stat.mtime instead. - log->Info(XrdCl::AppMsg, "FillFileMapRecurse() could not get access time for %s, trying stat.\n", np.c_str()); + TRACE(Warning, "FillFileMapRecurse() could not get access time for " << np << ", trying stat"); XrdOss* oss = Cache::GetInstance().GetOss(); struct stat fstat; @@ -100,18 +107,14 @@ void FillFileMapRecurse( XrdOssDF* iOssDF, const std::string& path, FPurgeState& if (oss->Stat(np.c_str(), &fstat) == XrdOssOK) { accessTime = fstat.st_mtime; - log->Info(XrdCl::AppMsg, "FillFileMapRecurse() determined access time for %s via stat: %lld\n", - np.c_str(), accessTime); - + TRACE(Dump, "FillFileMapRecurse() have access time for " << np << " via stat: " << accessTime); purgeState.checkFile(accessTime, np.c_str(), cinfo.GetNDownloadedBytes()); } else { // This really shouldn't happen ... but if it does remove cinfo and the data file right away. - log->Warning(XrdCl::AppMsg, "FillFileMapRecurse() could not get access time for %s. Purging directly.\n", - np.c_str()); - + TRACE(Warning, "FillFileMapRecurse() could not get access time for " << np); oss->Unlink(np.c_str()); np = np.substr(0, np.size() - strlen(XrdFileCache::Info::m_infoExtension)); oss->Unlink(np.c_str()); @@ -128,7 +131,7 @@ void FillFileMapRecurse( XrdOssDF* iOssDF, const std::string& path, FPurgeState& } } } - +} void Cache::CacheDirCleanup() { // check state every sleep seconds @@ -145,17 +148,17 @@ void Cache::CacheDirCleanup() long long bytesToRemove = 0; if (oss->StatVS(&sP, "public", 1) < 0) { - clLog()->Error(XrdCl::AppMsg, "Cache::CacheDirCleanup() can't get statvs for dir [%s] \n", m_configuration.m_cache_dir.c_str()); + TRACE(Error, "Cache::CacheDirCleanup() can't get statvs for dir " << m_configuration.m_cache_dir.c_str()); exit(1); } else { long long ausage = sP.Total - sP.Free; - clLog()->Info(XrdCl::AppMsg, "Cache::CacheDirCleanup() occupates disk space == %lld", ausage); + TRACE(Debug, "Cache::CacheDirCleanup() occupates disk space == " << ausage); if (ausage > m_configuration.m_diskUsageHWM) { bytesToRemove = ausage - m_configuration.m_diskUsageLWM; - clLog()->Info(XrdCl::AppMsg, "Cache::CacheDirCleanup() need space for %lld bytes", bytesToRemove); + TRACE(Debug, "Cache::CacheDirCleanup() need space for " << bytesToRemove << " bytes"); } } @@ -180,8 +183,7 @@ void Cache::CacheDirCleanup() { bytesToRemove -= fstat.st_size; oss->Unlink(path.c_str()); - clLog()->Info(XrdCl::AppMsg, "Cache::CacheDirCleanup() removed %s size %lld", - path.c_str(), fstat.st_size); + TRACE(Info, "Cache::CacheDirCleanup() removed file:" << path << " size: " << fstat.st_size); } // remove data file @@ -190,8 +192,7 @@ void Cache::CacheDirCleanup() { bytesToRemove -= it->second.nByte; oss->Unlink(path.c_str()); - clLog()->Info(XrdCl::AppMsg, "Cache::CacheDirCleanup() removed %s bytes %lld, stat_size %lld", - path.c_str(), it->second.nByte, fstat.st_size); + TRACE(Info, "Cache::CacheDirCleanup() removed file: %s " << path << " size " << it->second.nByte); } if (bytesToRemove <= 0) diff --git a/src/XrdFileCache/XrdFileCacheTrace.hh b/src/XrdFileCache/XrdFileCacheTrace.hh new file mode 100644 index 00000000000..77e75353f69 --- /dev/null +++ b/src/XrdFileCache/XrdFileCacheTrace.hh @@ -0,0 +1,42 @@ +#ifndef _XRDFILECACHE_TRACE_H +#define _XRDFILECACHE_TRACE_H + +// Trace flags +// +#define TRACE_None 0 +#define TRACE_Error 1 +#define TRACE_Warning 2 +#define TRACE_Info 3 +#define TRACE_Debug 4 +#define TRACE_Dump 5 + +#ifndef NODEBUG + +#include "XrdSys/XrdSysHeaders.hh" +#include "XrdOuc/XrdOucTrace.hh" + +#ifndef XRD_TRACE +#define XRD_TRACE GetTrace()-> +#endif + +#define TRACE(act, x) \ + if (XRD_TRACE What >= TRACE_ ## act) \ + {XRD_TRACE Beg(m_traceID); cerr <= TRACE_ ## act) \ + {XRD_TRACE Beg(m_traceID); cerr <Path(); XRD_TRACE End();} + +#define TRACEF(act, x) \ + if (XRD_TRACE What >= TRACE_ ## act) \ + {XRD_TRACE Beg(m_traceID); cerr <Debug(XrdCl::AppMsg, "ReadV for %d chunks", n); + TRACEF(Dump, "ReadV for %d chunks " << n); int bytesRead = 0; @@ -153,7 +154,7 @@ int File::ReadV (const XrdOucIOVec *readV, int n) delete i->arr; - clLog()->Debug(XrdCl::AppMsg, "VRead exit, total = %d", bytesRead); + TRACEF(Dump, "VRead exit, total = " << bytesRead); return bytesRead; } @@ -170,18 +171,18 @@ bool File::VReadPreProcess(const XrdOucIOVec *readV, int n, ReadVBlockListRAM& b for (int block_idx = blck_idx_first; block_idx <= blck_idx_last; ++block_idx) { - clLog()->Debug(XrdCl::AppMsg, "VReadPreProcess chunk %lld@%lld", readV[iov_idx].size, readV[iov_idx].offset); + TRACEF(Dump, "VReadPreProcess chunk "<< readV[iov_idx].size << "@"<< readV[iov_idx].offset); BlockMap_i bi = m_block_map.find(block_idx); if (bi != m_block_map.end()) { if ( blocks_to_process.AddEntry(bi->second, iov_idx)) inc_ref_count(bi->second); - clLog()->Debug(XrdCl::AppMsg, "VReadPreProcess block %d in map", block_idx); + TRACEF(Dump, "VReadPreProcess block "<< block_idx <<" in map"); } else if (m_cfi.TestBit(offsetIdx(block_idx))) { blocks_on_disk.AddEntry(block_idx, iov_idx); - clLog()->Debug(XrdCl::AppMsg, "VReadPreProcess block %d , chunk idx = %d on disk", block_idx,iov_idx ); + TRACEF(Dump, "VReadPreProcess block "<< block_idx <<" , chunk idx = " << iov_idx << " on disk"); } else { if ( Cache::GetInstance().HaveFreeWritingSlots() && Cache::GetInstance().RequestRAMBlock()) @@ -189,7 +190,7 @@ bool File::VReadPreProcess(const XrdOucIOVec *readV, int n, ReadVBlockListRAM& b Block *b = RequestBlock(block_idx, false); if (!b) return false; blocks_to_process.AddEntry(b, iov_idx); - clLog()->Debug(XrdCl::AppMsg, "VReadPreProcess request block %d", block_idx); + TRACEF(Dump, "VReadPreProcess request block " << block_idx); inc_ref_count(b); } else { @@ -199,7 +200,7 @@ bool File::VReadPreProcess(const XrdOucIOVec *readV, int n, ReadVBlockListRAM& b const long long BS = m_cfi.GetBufferSize(); overlap(block_idx, BS, readV[iov_idx].offset, readV[iov_idx].size, off, blk_off, size); chunkVec.push_back(XrdOucIOVec2(readV[iov_idx].data+off, BS*block_idx + blk_off,size)); - clLog()->Debug(XrdCl::AppMsg, "VReadPreProcess direct read %d", block_idx); + TRACEF(Dump, "VReadPreProcess direct read " << block_idx); } } } @@ -226,7 +227,7 @@ int File::VReadFromDisk(const XrdOucIOVec *readV, int n, ReadVBlockListDisk& blo long long size; // size to copy - clLog()->Debug(XrdCl::AppMsg, "VReadFromDisk block=%d chunk=%d", blockIdx, chunkIdx); + TRACEF(Dump, "VReadFromDisk block= " << blockIdx <<" chunk=" << chunkIdx); overlap(blockIdx, m_cfi.GetBufferSize(), readV[chunkIdx].offset, readV[chunkIdx].size, off, blk_off, size); int rs = m_output->Read(readV[chunkIdx].data + off, blockIdx*m_cfi.GetBufferSize() + blk_off - m_offset, size); @@ -234,10 +235,8 @@ int File::VReadFromDisk(const XrdOucIOVec *readV, int n, ReadVBlockListDisk& blo bytes_read += rs; } else { - // ofs read shoul set the errno - - clLog()->Error(XrdCl::AppMsg, "VReadFromDisk FAILED block=%d chunk=%d off=%lld, blk_off=%lld, size=%lld, chunfoff =%lld", blockIdx, chunkIdx, off, blk_off, size,readV[chunkIdx].offset ); - + // ofs read should set the errno + TRACEF(Error, "VReadFromDisk FAILED block=" << blockIdx << " chunk=" << chunkIdx << " off= " << off << " blk_off=" << blk_off << " size = " << size << "chunOff " << readV[chunkIdx].offset); return -1; } } @@ -311,6 +310,6 @@ int File::VReadProcessBlocks(const XrdOucIOVec *readV, int n, finished.clear(); } - clLog()->Info(XrdCl::AppMsg, "VReadProcessBlocks total read == %d", bytes_read); + TRACEF(Dump, "VReadProcessBlocks total read " << bytes_read); return bytes_read; }