diff --git a/src/jrd/jrd.h b/src/jrd/jrd.h index 58b086c50b..33557d4129 100644 --- a/src/jrd/jrd.h +++ b/src/jrd/jrd.h @@ -507,7 +507,7 @@ public: void bumpRelStats(const RelStatType index, SLONG relation_id) { reqStat->bumpRelValue(index, relation_id); - //traStat->bumpRelValue(index, relation_id); + traStat->bumpRelValue(index, relation_id); //attStat->bumpRelValue(index, relation_id); //dbbStat->bumpRelValue(index, relation_id); } diff --git a/src/jrd/ntrace.h b/src/jrd/ntrace.h index 6f696c3b4f..e9a32f5295 100644 --- a/src/jrd/ntrace.h +++ b/src/jrd/ntrace.h @@ -42,6 +42,14 @@ enum ntrace_connection_kind_t connection_service }; +enum ntrace_process_state_t +{ + process_state_started = 1, + process_state_finished, + process_state_failed, + process_state_progress +}; + class TraceBaseConnection : public Firebird::IVersioned { public: @@ -184,6 +192,18 @@ public: #define FB_TRACE_STATUS_VERSION (FB_VERSIONED_VERSION + 4) +class TraceSweepInfo : public Firebird::IVersioned +{ +public: + virtual TraNumber FB_CARG getOIT() = 0; + virtual TraNumber FB_CARG getOST() = 0; + virtual TraNumber FB_CARG getOAT() = 0; + virtual TraNumber FB_CARG getNext() = 0; + virtual PerformanceInfo* FB_CARG getPerf() = 0; +}; +#define FB_TRACE_SWEEP_INFO_VERSION (FB_VERSIONED_VERSION + 5) + + // Plugin-specific argument. Passed by the engine to each hook typedef void* ntrace_object_t; @@ -325,8 +345,12 @@ public: // Errors happened virtual ntrace_boolean_t FB_CARG trace_event_error(TraceBaseConnection* connection, TraceStatusVector* status, const char* function) = 0; + + // Sweep activity + virtual ntrace_boolean_t FB_CARG trace_event_sweep(TraceDatabaseConnection* connection, TraceSweepInfo* sweep, + ntrace_process_state_t sweep_state) = 0; }; -#define FB_TRACE_PLUGIN_VERSION (FB_REFCOUNTED_VERSION + 19) +#define FB_TRACE_PLUGIN_VERSION (FB_REFCOUNTED_VERSION + 20) // Trace plugin second level factory (this is what is known to PluginManager as "trace plugin") class TraceFactory : public Firebird::IPluginBase @@ -361,6 +385,7 @@ enum TraceEvent TRACE_EVENT_SERVICE_QUERY, TRACE_EVENT_SERVICE_DETACH, TRACE_EVENT_ERROR, + TRACE_EVENT_SWEEP, TRACE_EVENT_MAX // keep it last }; diff --git a/src/jrd/tra.cpp b/src/jrd/tra.cpp index f3c8a181dd..e5841f936e 100644 --- a/src/jrd/tra.cpp +++ b/src/jrd/tra.cpp @@ -1619,6 +1619,10 @@ bool TRA_sweep(thread_db* tdbb, jrd_tra* trans) if (dbb->dbb_flags & DBB_sweep_in_progress) return true; + if (tdbb->getAttachment()->att_flags & ATT_no_cleanup) { + return true; + } + // fill out a lock block, zeroing it out first Lock temp_lock(tdbb, 0, LCK_sweep, trans); @@ -1660,6 +1664,7 @@ bool TRA_sweep(thread_db* tdbb, jrd_tra* trans) TraNumber transaction_oldest_active = transaction->tra_oldest_active; tdbb->setTransaction(transaction); + TraceSweepEvent traceSweep(tdbb); // The garbage collector runs asynchronously with respect to // our database sweep. This isn't good enough since we must @@ -1670,7 +1675,7 @@ bool TRA_sweep(thread_db* tdbb, jrd_tra* trans) transaction->tra_attachment->att_flags &= ~ATT_notify_gc; - if (VIO_sweep(tdbb, transaction)) + if (VIO_sweep(tdbb, transaction, &traceSweep)) { const ULONG base = transaction->tra_oldest & ~TRA_MASK; TraNumber active = transaction->tra_oldest; @@ -1711,7 +1716,11 @@ bool TRA_sweep(thread_db* tdbb, jrd_tra* trans) header->hdr_oldest_transaction = MIN(active, (ULONG) transaction_oldest_active); } + traceSweep.update(header); + CCH_RELEASE(tdbb, &window); + + traceSweep.report(process_state_finished); } if (!trans) @@ -1725,6 +1734,8 @@ bool TRA_sweep(thread_db* tdbb, jrd_tra* trans) } // try catch (const Firebird::Exception& ex) { + iscLogException("Error during sweep:", ex); + Firebird::stuff_exception(tdbb->tdbb_status_vector, ex); try { if (!trans && transaction) @@ -3359,3 +3370,103 @@ UserManagement* jrd_tra::getUserManagement() return tra_user_management; } + +/// class TraceSweepEvent + +TraceSweepEvent::TraceSweepEvent(thread_db* tdbb) +{ + m_tdbb = tdbb; + + WIN window(HEADER_PAGE_NUMBER); + Ods::header_page *header = (Ods::header_page*) CCH_FETCH(m_tdbb, &window, LCK_read, pag_header); + + m_sweep_info.update(header); + CCH_RELEASE(m_tdbb, &window); + + Attachment* att = m_tdbb->getAttachment(); + + gds__log("Sweep is started by %s\n" + "\tDatabase \"%s\" \n" + "\tOIT %lu, OAT %lu, OST %lu, Next %lu", + att->att_user->usr_user_name.c_str(), + att->att_filename.c_str(), + m_sweep_info.getOIT(), + m_sweep_info.getOAT(), + m_sweep_info.getOST(), + m_sweep_info.getNext()); + + TraceManager* trace_mgr = att->att_trace_manager; + + m_need_trace = trace_mgr->needs(TRACE_EVENT_SWEEP); + + if (!m_need_trace) + return; + + m_start_clock = fb_utils::query_performance_counter(); + + TraceConnectionImpl conn(att); + trace_mgr->event_sweep(&conn, &m_sweep_info, process_state_started); + + m_relation_clock = fb_utils::query_performance_counter(); + m_relation_stats.assign(m_tdbb->getTransaction()->tra_stats); +} + + +TraceSweepEvent::~TraceSweepEvent() +{ + m_tdbb->setRequest(NULL); + report(process_state_failed); +} + + +void TraceSweepEvent::report(ntrace_process_state_t state, jrd_rel* relation) +{ + Attachment* att = m_tdbb->getAttachment(); + + if (state == process_state_finished) + { + gds__log("Sweep is finished\n" + "\tDatabase \"%s\" \n" + "\tOIT %lu, OAT %lu, OST %lu, Next %lu", + att->att_filename.c_str(), + m_sweep_info.getOIT(), + m_sweep_info.getOAT(), + m_sweep_info.getOST(), + m_sweep_info.getNext()); + } + + if (!m_need_trace) + return; + + Database* dbb = m_tdbb->getDatabase(); + TraceManager* trace_mgr = att->att_trace_manager; + + TraceConnectionImpl conn(att); + + if (relation && relation->rel_name.isEmpty()) + { + // don't accumulate per-relation stats for metadata query below + MET_lookup_relation_id(m_tdbb, relation->rel_id, false); + } + + // we need to compare stats against zero base + if (state != process_state_progress) + m_relation_stats.reset(); + + jrd_tra* tran = m_tdbb->getTransaction(); + + TraceRuntimeStats stats(att, &m_relation_stats, + state == process_state_progress ? &tran->tra_stats : &att->att_stats, + fb_utils::query_performance_counter() - (state == process_state_progress ? + m_relation_clock : m_start_clock), + 0); + + m_relation_clock = fb_utils::query_performance_counter(); + m_relation_stats.assign(m_tdbb->getTransaction()->tra_stats); + + m_sweep_info.setPerf(stats.getPerf()); + trace_mgr->event_sweep(&conn, &m_sweep_info, state); + + if (state == process_state_failed || state == process_state_finished) + m_need_trace = false; +} diff --git a/src/jrd/trace/TraceJrdHelpers.h b/src/jrd/trace/TraceJrdHelpers.h index 5a1e332000..e91045a070 100644 --- a/src/jrd/trace/TraceJrdHelpers.h +++ b/src/jrd/trace/TraceJrdHelpers.h @@ -412,6 +412,31 @@ private: }; +class TraceSweepEvent +{ + // implementation is at tra.cpp +public: + TraceSweepEvent(thread_db* tdbb); + + ~TraceSweepEvent(); + + void update(const Ods::header_page* header) + { + m_sweep_info.update(header); + } + + void report(ntrace_process_state_t state, jrd_rel* relation = 0); + +private: + bool m_need_trace; + thread_db* m_tdbb; + TraceSweepImpl m_sweep_info; + SINT64 m_start_clock; + SINT64 m_relation_clock; + RuntimeStatistics m_relation_stats; +}; + + } // namespace Jrd #endif // JRD_TRACE_JRD_HELPERS_H diff --git a/src/jrd/trace/TraceManager.cpp b/src/jrd/trace/TraceManager.cpp index 934737559b..3f5b09f552 100644 --- a/src/jrd/trace/TraceManager.cpp +++ b/src/jrd/trace/TraceManager.cpp @@ -485,4 +485,12 @@ void TraceManager::event_error(TraceBaseConnection* connection, TraceStatusVecto (connection, status, function)); } + +void TraceManager::event_sweep(TraceDatabaseConnection* connection, TraceSweepInfo* sweep, + ntrace_process_state_t sweep_state) +{ + EXECUTE_HOOKS(trace_event_sweep, + (connection, sweep, sweep_state)); +} + } diff --git a/src/jrd/trace/TraceManager.h b/src/jrd/trace/TraceManager.h index f59e4471f1..7cb89b129c 100644 --- a/src/jrd/trace/TraceManager.h +++ b/src/jrd/trace/TraceManager.h @@ -111,6 +111,9 @@ public: void event_error(TraceBaseConnection* connection, TraceStatusVector* status, const char* function); + void event_sweep(TraceDatabaseConnection* connection, TraceSweepInfo* sweep, + ntrace_process_state_t sweep_state); + typedef ntrace_mask_t NotificationNeeds; inline bool needs(TraceEvent e) diff --git a/src/jrd/trace/TraceObjects.h b/src/jrd/trace/TraceObjects.h index 244630b641..4704b69365 100644 --- a/src/jrd/trace/TraceObjects.h +++ b/src/jrd/trace/TraceObjects.h @@ -422,6 +422,45 @@ private: Firebird::string m_error; }; +class TraceSweepImpl : public Firebird::AutoIface +{ +public: + TraceSweepImpl() + { + m_oit = 0; + m_ost = 0; + m_oat = 0; + m_next = 0; + m_perf = 0; + } + + void update(const Ods::header_page* header) + { + m_oit = header->hdr_oldest_transaction; + m_ost = header->hdr_oldest_snapshot; + m_oat = header->hdr_oldest_active; + m_next = header->hdr_next_transaction; + } + + void setPerf(PerformanceInfo* perf) + { + m_perf = perf; + } + + virtual TraNumber FB_CARG getOIT() { return m_oit; }; + virtual TraNumber FB_CARG getOST() { return m_ost; }; + virtual TraNumber FB_CARG getOAT() { return m_oat; }; + virtual TraNumber FB_CARG getNext() { return m_next; }; + virtual PerformanceInfo* FB_CARG getPerf() { return m_perf; }; + +private: + TraNumber m_oit; + TraNumber m_ost; + TraNumber m_oat; + TraNumber m_next; + PerformanceInfo* m_perf; +}; + } // namespace Jrd #endif // JRD_TRACE_OBJECTS_H diff --git a/src/jrd/vio.cpp b/src/jrd/vio.cpp index 288bc0235a..ad2c0396e6 100644 --- a/src/jrd/vio.cpp +++ b/src/jrd/vio.cpp @@ -91,6 +91,8 @@ #include "../jrd/Function.h" #include "../common/StatusArg.h" #include "../jrd/GarbageCollector.h" +#include "../jrd/trace/TraceManager.h" +#include "../jrd/trace/TraceJrdHelpers.h" using namespace Jrd; using namespace Firebird; @@ -3210,7 +3212,7 @@ void VIO_store(thread_db* tdbb, record_param* rpb, jrd_tra* transaction) } -bool VIO_sweep(thread_db* tdbb, jrd_tra* transaction) +bool VIO_sweep(thread_db* tdbb, jrd_tra* transaction, TraceSweepEvent* traceSweep) { /************************************** * @@ -3253,6 +3255,7 @@ bool VIO_sweep(thread_db* tdbb, jrd_tra* transaction) for (size_t i = 1; (vector = attachment->att_relations) && i < vector->count(); i++) { + bool haveRecs = false; if ((relation = (*vector)[i]) && !(relation->rel_flags & (REL_deleted | REL_deleting)) && relation->getPages(tdbb)->rel_pages) { @@ -3275,7 +3278,13 @@ bool VIO_sweep(thread_db* tdbb, jrd_tra* transaction) JRD_reschedule(tdbb, SWEEP_QUANTUM, true); } transaction->tra_oldest_active = dbb->dbb_oldest_snapshot; + haveRecs = true; } + + if (haveRecs) { + traceSweep->report(process_state_progress, relation); + } + --relation->rel_sweep_count; --relation->rel_scan_count; } diff --git a/src/jrd/vio_proto.h b/src/jrd/vio_proto.h index 37c1c199e9..f5dc96cef7 100644 --- a/src/jrd/vio_proto.h +++ b/src/jrd/vio_proto.h @@ -34,6 +34,7 @@ namespace Jrd { struct record_param; class Savepoint; class Format; + class TraceSweepEvent; } void VIO_backout(Jrd::thread_db*, Jrd::record_param*, const Jrd::jrd_tra*); @@ -58,7 +59,7 @@ Jrd::Record* VIO_record(Jrd::thread_db*, Jrd::record_param*, const Jrd::Format*, void VIO_refetch_record(Jrd::thread_db*, Jrd::record_param*, Jrd::jrd_tra*); void VIO_start_save_point(Jrd::thread_db*, Jrd::jrd_tra*); void VIO_store(Jrd::thread_db*, Jrd::record_param*, Jrd::jrd_tra*); -bool VIO_sweep(Jrd::thread_db*, Jrd::jrd_tra*); +bool VIO_sweep(Jrd::thread_db*, Jrd::jrd_tra*, Jrd::TraceSweepEvent*); void VIO_verb_cleanup(Jrd::thread_db*, Jrd::jrd_tra*); IPTR VIO_savepoint_large(const Jrd::Savepoint*, IPTR); void VIO_temp_cleanup(Jrd::jrd_tra*); diff --git a/src/utilities/ntrace/TracePluginImpl.cpp b/src/utilities/ntrace/TracePluginImpl.cpp index 7e7e391e4b..fe64a0601c 100644 --- a/src/utilities/ntrace/TracePluginImpl.cpp +++ b/src/utilities/ntrace/TracePluginImpl.cpp @@ -1971,6 +1971,59 @@ void TracePluginImpl::log_event_error(TraceBaseConnection* connection, TraceStat logRecordError(event_type.c_str(), connection, status); } +void TracePluginImpl::log_event_sweep(TraceDatabaseConnection* connection, TraceSweepInfo* sweep, + ntrace_process_state_t sweep_state) +{ + if (sweep_state == process_state_started || + sweep_state == process_state_finished) + { + record.printf("\nTransaction counters:\n" + "\tOldest interesting %10ld\n" + "\tOldest active %10ld\n" + "\tOldest snapshot %10ld\n" + "\tNext transaction %10ld\n", + sweep->getOIT(), + sweep->getOAT(), + sweep->getOST(), + sweep->getNext() + ); + } + + PerformanceInfo* info = sweep->getPerf(); + if (info) + { + appendGlobalCounts(info); + appendTableCounts(info); + } + + const char* event_type = NULL; + switch (sweep_state) + { + case process_state_started: + event_type = "SWEEP_START"; + break; + + case process_state_finished: + event_type = "SWEEP_FINISH"; + break; + + case process_state_failed: + event_type = "SWEEP_FAILED"; + break; + + case process_state_progress: + event_type = "SWEEP_PROGRESS"; + break; + + default: + fb_assert(false); + event_type = "Unknown SWEEP process state"; + break; + } + + logRecordConn(event_type, connection); +} + //***************************** PLUGIN INTERFACE ******************************** int TracePluginImpl::release() @@ -2339,3 +2392,20 @@ ntrace_boolean_t TracePluginImpl::trace_event_error(TraceBaseConnection* connect return false; } } + +ntrace_boolean_t TracePluginImpl::trace_event_sweep(TraceDatabaseConnection* connection, TraceSweepInfo* sweep, + ntrace_process_state_t sweep_state) +{ + try + { + MasterInterfacePtr()->upgradeInterface(connection, FB_TRACE_CONNECTION_VERSION, upInfo); + MasterInterfacePtr()->upgradeInterface(sweep, FB_TRACE_SWEEP_INFO_VERSION, upInfo); + log_event_sweep(connection, sweep, sweep_state); + return true; + } + catch(const Firebird::Exception& ex) + { + marshal_exception(ex); + return false; + } +} diff --git a/src/utilities/ntrace/TracePluginImpl.h b/src/utilities/ntrace/TracePluginImpl.h index 187ad7399c..d08b0cc4c1 100644 --- a/src/utilities/ntrace/TracePluginImpl.h +++ b/src/utilities/ntrace/TracePluginImpl.h @@ -255,6 +255,8 @@ private: void log_event_error(TraceBaseConnection* connection, TraceStatusVector* status, const char* function); + void log_event_sweep(TraceDatabaseConnection* connection, TraceSweepInfo* sweep, ntrace_process_state_t sweep_state); + // TracePlugin implementation int FB_CARG release(); const char* FB_CARG trace_get_error(); @@ -306,6 +308,10 @@ private: // Errors happened virtual ntrace_boolean_t FB_CARG trace_event_error(TraceBaseConnection* connection, TraceStatusVector* status, const char* function); + + // Sweep activity + virtual ntrace_boolean_t FB_CARG trace_event_sweep(TraceDatabaseConnection* connection, TraceSweepInfo* sweep, + ntrace_process_state_t sweep_state); }; diff --git a/src/utilities/ntrace/fbtrace.conf b/src/utilities/ntrace/fbtrace.conf index 68270e4a11..ec9397b49a 100644 --- a/src/utilities/ntrace/fbtrace.conf +++ b/src/utilities/ntrace/fbtrace.conf @@ -87,6 +87,9 @@ database # Put errors happened #log_errors false + # Sweep activity + #log_sweep false + # Print access path (plan) with sql statement #print_plan = false diff --git a/src/utilities/ntrace/paramtable.h b/src/utilities/ntrace/paramtable.h index 16890a33bd..e0f1a533fa 100644 --- a/src/utilities/ntrace/paramtable.h +++ b/src/utilities/ntrace/paramtable.h @@ -58,6 +58,7 @@ BOOL_PARAMETER(log_blr_requests, false) BOOL_PARAMETER(print_blr, false) BOOL_PARAMETER(log_dyn_requests, false) BOOL_PARAMETER(print_dyn, false) +BOOL_PARAMETER(log_sweep, false) UINT_PARAMETER(max_sql_length, 300) UINT_PARAMETER(max_blr_length, 500) UINT_PARAMETER(max_dyn_length, 500)