Nico/Viano-Core
1
0 Fork 0
Code Issues Pull Requests Actions 8 Packages Projects Releases Wiki Activity

Core/Logging: Performance-related tweaks to logging system

Browse Source 
All sLog->out* functions (except outCommand atm) are replaced with TC_LOG_* macros.
    Memleak fix
This commit is contained in:
Spp committed 2013-05-13 15:07:36 +02:00
1 parent 243c325ca4
commit d1677b2db0
240 files changed
+4580 -4563
Download Patch File Download Diff File Expand all files Collapse all files

No files matched your search

src/server/game/Server/WorldSession.cpp
+29 -29
View File
@@ -210,8 +210,8 @@ void WorldSession::SendPacket(WorldPacket const* packet)
{
uint64 minTime = uint64(cur_time - lastTime);
uint64 fullTime = uint64(lastTime - firstTime);
sLog->outInfo(LOG_FILTER_GENERAL, "Send all time packets count: " UI64FMTD " bytes: " UI64FMTD " avr.count/sec: %f avr.bytes/sec: %f time: %u", sendPacketCount, sendPacketBytes, float(sendPacketCount)/fullTime, float(sendPacketBytes)/fullTime, uint32(fullTime));
sLog->outInfo(LOG_FILTER_GENERAL, "Send last min packets count: " UI64FMTD " bytes: " UI64FMTD " avr.count/sec: %f avr.bytes/sec: %f", sendLastPacketCount, sendLastPacketBytes, float(sendLastPacketCount)/minTime, float(sendLastPacketBytes)/minTime);
TC_LOG_INFO(LOG_FILTER_GENERAL, "Send all time packets count: " UI64FMTD " bytes: " UI64FMTD " avr.count/sec: %f avr.bytes/sec: %f time: %u", sendPacketCount, sendPacketBytes, float(sendPacketCount)/fullTime, float(sendPacketBytes)/fullTime, uint32(fullTime));
TC_LOG_INFO(LOG_FILTER_GENERAL, "Send last min packets count: " UI64FMTD " bytes: " UI64FMTD " avr.count/sec: %f avr.bytes/sec: %f", sendLastPacketCount, sendLastPacketBytes, float(sendLastPacketCount)/minTime, float(sendLastPacketBytes)/minTime);
lastTime = cur_time;
sendLastPacketCount = 1;
@@ -232,7 +232,7 @@ void WorldSession::QueuePacket(WorldPacket* new_packet)
/// Logging helper for unexpected opcodes
void WorldSession::LogUnexpectedOpcode(WorldPacket* packet, const char* status, const char *reason)
{
sLog->outError(LOG_FILTER_OPCODES, "Received unexpected opcode %s Status: %s Reason: %s from %s",
TC_LOG_ERROR(LOG_FILTER_OPCODES, "Received unexpected opcode %s Status: %s Reason: %s from %s",
GetOpcodeNameForLogging(packet->GetOpcode()).c_str(), status, reason, GetPlayerInfo().c_str());
}
@@ -242,7 +242,7 @@ void WorldSession::LogUnprocessedTail(WorldPacket* packet)
if (!sLog->ShouldLog(LOG_FILTER_OPCODES, LOG_LEVEL_TRACE) || packet->rpos() >= packet->wpos())
return;
sLog->outTrace(LOG_FILTER_OPCODES, "Unprocessed tail data (read stop at %u from %u) Opcode %s from %s",
TC_LOG_TRACE(LOG_FILTER_OPCODES, "Unprocessed tail data (read stop at %u from %u) Opcode %s from %s",
uint32(packet->rpos()), uint32(packet->wpos()), GetOpcodeNameForLogging(packet->GetOpcode()).c_str(), GetPlayerInfo().c_str());
packet->print_storage();
}
@@ -276,7 +276,7 @@ bool WorldSession::Update(uint32 diff, PacketFilter& updater)
{
if (packet->GetOpcode() >= NUM_MSG_TYPES)
{
sLog->outError(LOG_FILTER_OPCODES, "Received non-existed opcode %s from %s", GetOpcodeNameForLogging(packet->GetOpcode()).c_str()
TC_LOG_ERROR(LOG_FILTER_OPCODES, "Received non-existed opcode %s from %s", GetOpcodeNameForLogging(packet->GetOpcode()).c_str()
, GetPlayerInfo().c_str());
sScriptMgr->OnUnknownPacketReceive(m_Socket, WorldPacket(*packet));
}
@@ -302,7 +302,7 @@ bool WorldSession::Update(uint32 diff, PacketFilter& updater)
deletePacket = false;
QueuePacket(packet);
//! Log
sLog->outDebug(LOG_FILTER_NETWORKIO, "Re-enqueueing packet with opcode %s with with status STATUS_LOGGEDIN. "
TC_LOG_DEBUG(LOG_FILTER_NETWORKIO, "Re-enqueueing packet with opcode %s with with status STATUS_LOGGEDIN. "
"Player is currently not in world yet.", GetOpcodeNameForLogging(packet->GetOpcode()).c_str());
}
}
@@ -356,18 +356,18 @@ bool WorldSession::Update(uint32 diff, PacketFilter& updater)
LogUnprocessedTail(packet);
break;
case STATUS_NEVER:
sLog->outError(LOG_FILTER_OPCODES, "Received not allowed opcode %s from %s", GetOpcodeNameForLogging(packet->GetOpcode()).c_str()
TC_LOG_ERROR(LOG_FILTER_OPCODES, "Received not allowed opcode %s from %s", GetOpcodeNameForLogging(packet->GetOpcode()).c_str()
, GetPlayerInfo().c_str());
break;
case STATUS_UNHANDLED:
sLog->outDebug(LOG_FILTER_OPCODES, "Received not handled opcode %s from %s", GetOpcodeNameForLogging(packet->GetOpcode()).c_str()
TC_LOG_DEBUG(LOG_FILTER_OPCODES, "Received not handled opcode %s from %s", GetOpcodeNameForLogging(packet->GetOpcode()).c_str()
, GetPlayerInfo().c_str());
break;
}
}
catch(ByteBufferException &)
{
sLog->outError(LOG_FILTER_GENERAL, "WorldSession::Update ByteBufferException occured while parsing a packet (opcode: %u) from client %s, accountid=%i. Skipped packet.",
TC_LOG_ERROR(LOG_FILTER_GENERAL, "WorldSession::Update ByteBufferException occured while parsing a packet (opcode: %u) from client %s, accountid=%i. Skipped packet.",
packet->GetOpcode(), GetRemoteAddress().c_str(), GetAccountId());
packet->hexlike();
}
@@ -525,7 +525,7 @@ void WorldSession::LogoutPlayer(bool save)
// e.g if he got disconnected during a transfer to another map
// calls to GetMap in this case may cause crashes
_player->CleanupsBeforeDelete();
sLog->outInfo(LOG_FILTER_CHARACTER, "Account: %d (IP: %s) Logout Character:[%s] (GUID: %u) Level: %d",
TC_LOG_INFO(LOG_FILTER_CHARACTER, "Account: %d (IP: %s) Logout Character:[%s] (GUID: %u) Level: %d",
GetAccountId(), GetRemoteAddress().c_str(), _player->GetName().c_str(), _player->GetGUIDLow(), _player->getLevel());
if (Map* _map = _player->FindMap())
_map->RemovePlayerFromMap(_player, true);
@@ -536,7 +536,7 @@ void WorldSession::LogoutPlayer(bool save)
//! Client will respond by sending 3x CMSG_CANCEL_TRADE, which we currently dont handle
WorldPacket data(SMSG_LOGOUT_COMPLETE, 0);
SendPacket(&data);
sLog->outDebug(LOG_FILTER_NETWORKIO, "SESSION: Sent SMSG_LOGOUT_COMPLETE Message");
TC_LOG_DEBUG(LOG_FILTER_NETWORKIO, "SESSION: Sent SMSG_LOGOUT_COMPLETE Message");
//! Since each account can only have one online character at any given time, ensure all characters for active account are marked as offline
PreparedStatement* stmt = CharacterDatabase.GetPreparedStatement(CHAR_UPD_ACCOUNT_ONLINE);
@@ -599,25 +599,25 @@ const char *WorldSession::GetTrinityString(int32 entry) const
void WorldSession::Handle_NULL(WorldPacket& recvPacket)
{
sLog->outError(LOG_FILTER_OPCODES, "Received unhandled opcode %s from %s"
TC_LOG_ERROR(LOG_FILTER_OPCODES, "Received unhandled opcode %s from %s"
, GetOpcodeNameForLogging(recvPacket.GetOpcode()).c_str(), GetPlayerInfo().c_str());
}
void WorldSession::Handle_EarlyProccess(WorldPacket& recvPacket)
{
sLog->outError(LOG_FILTER_OPCODES, "Received opcode %s that must be processed in WorldSocket::OnRead from %s"
TC_LOG_ERROR(LOG_FILTER_OPCODES, "Received opcode %s that must be processed in WorldSocket::OnRead from %s"
, GetOpcodeNameForLogging(recvPacket.GetOpcode()).c_str(), GetPlayerInfo().c_str());
}
void WorldSession::Handle_ServerSide(WorldPacket& recvPacket)
{
sLog->outError(LOG_FILTER_OPCODES, "Received server-side opcode %s from %s"
TC_LOG_ERROR(LOG_FILTER_OPCODES, "Received server-side opcode %s from %s"
, GetOpcodeNameForLogging(recvPacket.GetOpcode()).c_str(), GetPlayerInfo().c_str());
}
void WorldSession::Handle_Deprecated(WorldPacket& recvPacket)
{
sLog->outError(LOG_FILTER_OPCODES, "Received deprecated opcode %s from %s"
TC_LOG_ERROR(LOG_FILTER_OPCODES, "Received deprecated opcode %s from %s"
, GetOpcodeNameForLogging(recvPacket.GetOpcode()).c_str(), GetPlayerInfo().c_str());
}
@@ -661,14 +661,14 @@ void WorldSession::LoadAccountData(PreparedQueryResult result, uint32 mask)
uint32 type = fields[0].GetUInt8();
if (type >= NUM_ACCOUNT_DATA_TYPES)
{
sLog->outError(LOG_FILTER_GENERAL, "Table `%s` have invalid account data type (%u), ignore.",
TC_LOG_ERROR(LOG_FILTER_GENERAL, "Table `%s` have invalid account data type (%u), ignore.",
mask == GLOBAL_CACHE_MASK ? "account_data" : "character_account_data", type);
continue;
}
if ((mask & (1 << type)) == 0)
{
sLog->outError(LOG_FILTER_GENERAL, "Table `%s` have non appropriate for table account data type (%u), ignore.",
TC_LOG_ERROR(LOG_FILTER_GENERAL, "Table `%s` have non appropriate for table account data type (%u), ignore.",
mask == GLOBAL_CACHE_MASK ? "account_data" : "character_account_data", type);
continue;
}
@@ -806,7 +806,7 @@ void WorldSession::ReadMovementInfo(WorldPacket &data, MovementInfo* mi)
{ \
if (check) \
{ \
sLog->outDebug(LOG_FILTER_UNITS, "WorldSession::ReadMovementInfo: Violation of MovementFlags found (%s). " \
TC_LOG_DEBUG(LOG_FILTER_UNITS, "WorldSession::ReadMovementInfo: Violation of MovementFlags found (%s). " \
"MovementFlags: %u, MovementFlags2: %u for player GUID: %u. Mask %u will be removed.", \
STRINGIZE(check), mi->GetMovementFlags(), mi->GetExtraMovementFlags(), GetPlayer()->GetGUIDLow(), maskToRemove); \
mi->RemoveMovementFlag((maskToRemove)); \
@@ -923,7 +923,7 @@ void WorldSession::ReadAddonsInfo(WorldPacket &data)
if (size > 0xFFFFF)
{
sLog->outError(LOG_FILTER_GENERAL, "WorldSession::ReadAddonsInfo addon info too big, size %u", size);
TC_LOG_ERROR(LOG_FILTER_GENERAL, "WorldSession::ReadAddonsInfo addon info too big, size %u", size);
return;
}
@@ -953,7 +953,7 @@ void WorldSession::ReadAddonsInfo(WorldPacket &data)
addonInfo >> enabled >> crc >> unk1;
sLog->outInfo(LOG_FILTER_GENERAL, "ADDON: Name: %s, Enabled: 0x%x, CRC: 0x%x, Unknown2: 0x%x", addonName.c_str(), enabled, crc, unk1);
TC_LOG_INFO(LOG_FILTER_GENERAL, "ADDON: Name: %s, Enabled: 0x%x, CRC: 0x%x, Unknown2: 0x%x", addonName.c_str(), enabled, crc, unk1);
AddonInfo addon(addonName, enabled, crc, 2, true);
@@ -961,15 +961,15 @@ void WorldSession::ReadAddonsInfo(WorldPacket &data)
if (savedAddon)
{
if (addon.CRC != savedAddon->CRC)
sLog->outInfo(LOG_FILTER_GENERAL, "ADDON: %s was known, but didn't match known CRC (0x%x)!", addon.Name.c_str(), savedAddon->CRC);
TC_LOG_INFO(LOG_FILTER_GENERAL, "ADDON: %s was known, but didn't match known CRC (0x%x)!", addon.Name.c_str(), savedAddon->CRC);
else
sLog->outInfo(LOG_FILTER_GENERAL, "ADDON: %s was known, CRC is correct (0x%x)", addon.Name.c_str(), savedAddon->CRC);
TC_LOG_INFO(LOG_FILTER_GENERAL, "ADDON: %s was known, CRC is correct (0x%x)", addon.Name.c_str(), savedAddon->CRC);
}
else
{
AddonMgr::SaveAddon(addon);
sLog->outInfo(LOG_FILTER_GENERAL, "ADDON: %s (0x%x) was not known, saving...", addon.Name.c_str(), addon.CRC);
TC_LOG_INFO(LOG_FILTER_GENERAL, "ADDON: %s (0x%x) was not known, saving...", addon.Name.c_str(), addon.CRC);
}
/// @todo Find out when to not use CRC/pubkey, and other possible states.
@@ -978,10 +978,10 @@ void WorldSession::ReadAddonsInfo(WorldPacket &data)
uint32 currentTime;
addonInfo >> currentTime;
sLog->outDebug(LOG_FILTER_NETWORKIO, "ADDON: CurrentTime: %u", currentTime);
TC_LOG_DEBUG(LOG_FILTER_NETWORKIO, "ADDON: CurrentTime: %u", currentTime);
}
else
sLog->outError(LOG_FILTER_GENERAL, "Addon packet uncompress error!");
TC_LOG_ERROR(LOG_FILTER_GENERAL, "Addon packet uncompress error!");
}
void WorldSession::SendAddonsInfo()
@@ -1020,7 +1020,7 @@ void WorldSession::SendAddonsInfo()
data << uint8(usepk);
if (usepk) // if CRC is wrong, add public key (client need it)
{
sLog->outInfo(LOG_FILTER_GENERAL, "ADDON: CRC (0x%x) for addon %s is wrong (does not match expected 0x%x), sending pubkey",
TC_LOG_INFO(LOG_FILTER_GENERAL, "ADDON: CRC (0x%x) for addon %s is wrong (does not match expected 0x%x), sending pubkey",
itr->CRC, itr->Name.c_str(), STANDARD_ADDON_CRC);
data.append(addonPublicKey, sizeof(addonPublicKey));
@@ -1180,7 +1180,7 @@ void WorldSession::LoadPermissions()
_RBACData = new RBACData(id, name, realmID);
_RBACData->LoadFromDB();
sLog->outDebug(LOG_FILTER_RBAC, "WorldSession::LoadPermissions [AccountId: %u, Name: %s, realmId: %d]",
TC_LOG_DEBUG(LOG_FILTER_RBAC, "WorldSession::LoadPermissions [AccountId: %u, Name: %s, realmId: %d]",
id, name.c_str(), realmID);
}
@@ -1195,7 +1195,7 @@ bool WorldSession::HasPermission(uint32 permission)
LoadPermissions();
bool hasPermission = _RBACData->HasPermission(permission);
sLog->outDebug(LOG_FILTER_RBAC, "WorldSession::HasPermission [AccountId: %u, Name: %s, realmId: %d]",
TC_LOG_DEBUG(LOG_FILTER_RBAC, "WorldSession::HasPermission [AccountId: %u, Name: %s, realmId: %d]",
_RBACData->GetId(), _RBACData->GetName().c_str(), realmID);
return hasPermission;
@@ -1203,7 +1203,7 @@ bool WorldSession::HasPermission(uint32 permission)
void WorldSession::InvalidateRBACData()
{
sLog->outDebug(LOG_FILTER_RBAC, "WorldSession::InvalidateRBACData [AccountId: %u, Name: %s, realmId: %d]",
TC_LOG_DEBUG(LOG_FILTER_RBAC, "WorldSession::InvalidateRBACData [AccountId: %u, Name: %s, realmId: %d]",
_RBACData->GetId(), _RBACData->GetName().c_str(), realmID);
delete _RBACData;
_RBACData = NULL;