Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

add log for txpool tx track #1046

Open
wants to merge 3 commits into
base: develop
Choose a base branch
from
Open

add log for txpool tx track #1046

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
cdc2d48
add log for txpool tx track
georgehao Sep 18, 2024
8be6ba1
Merge branch 'develop' into feat/add_log_for_long_sustain_tx
georgehao Sep 18, 2024
c79ee45
chore: auto version bump [bot]
georgehao Sep 18, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 11 additions & 2 deletions core/tx_pool.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -431,6 +431,7 @@ func (pool *TxPool) loop() {
if time.Since(pool.beats[addr]) > pool.config.Lifetime {
list := pool.queue[addr].Flatten()
for _, tx := range list {
log.Info("evict tx for timeout", "tx", tx.Hash().String())
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
log.Info("evict tx for timeout", "tx", tx.Hash().String())
log.Info("evict queue tx for timeout", "tx", tx.Hash().String())

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why do we want to add these logs (this and the others)? Just for debugging?

Better to add most of these as Debug logs, otherwise there will be too many logs during normal operation.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

image

for example, when I investigated the tx life cycle issue, I want know which tx affects this. If we add these logs, we can know what happened with the txs

Copy link
Member Author

@georgehao georgehao Sep 19, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just want display the tx active state in txpool to make us easy to investigate a tx track

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I also think it's not a good idea to spam INFO logs. Then the general logs output when running a normal node is just too overwhelming and one can't make sense out of it anymore. If need be better to move to DEBUG and run the nodes that should have create the metrics on debug level

Maybe it's worth thinking about the following (I'm not sure about exact capabilities Prometheus+Grafana): instead of logging this and parsing the logs, maybe we can use Prometheus to store different "events" per tx hash and transform them with some query. This way we can visualize whatever we're interested in and filter the "active tx".

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Prometheus+Grafana doesn't work for it. Metrics just show a trend of an event, they can't show specified info. for example, txpool_txfifecycle it just shows tx occupied time at different percentile ratios, but it can't show which tx cost how much, prometheus can't support that.

If you want to dig some tx why cost so much, I think there are two ways: 1) log, 2) trace. trace need a lot of development.

I also think it's not a good idea to spam INFO logs

for this, I think, it's not too bad. if the log really affect the geth's performance, we can downgrade the log level again

pool.removeTx(tx.Hash(), true)
}
queuedEvictionMeter.Mark(int64(len(list)))
Expand Down Expand Up @@ -865,7 +866,7 @@ func (pool *TxPool) add(tx *types.Transaction, local bool) (replaced bool, err e
pool.priced.Put(tx, isLocal)
pool.journalTx(from, tx)
pool.queueTxEvent(tx)
log.Trace("Pooled new executable transaction", "hash", hash, "from", from, "to", tx.To())
log.Info("Pooled new executable transaction", "hash", hash, "from", from, "to", tx.To())

// Successful promotion, bump the heartbeat
pool.beats[from] = time.Now()
Expand All @@ -887,7 +888,7 @@ func (pool *TxPool) add(tx *types.Transaction, local bool) (replaced bool, err e
}
pool.journalTx(from, tx)

log.Trace("Pooled new future transaction", "hash", hash, "from", from, "to", tx.To())
log.Info("Pooled new future transaction", "hash", hash, "from", from, "to", tx.To())
return replaced, nil
}

Expand Down Expand Up @@ -922,6 +923,7 @@ func (pool *TxPool) enqueueTx(hash common.Hash, tx *types.Transaction, local boo
if pool.all.Get(hash) == nil && !addAll {
log.Error("Missing transaction in lookup set, please report the issue", "hash", hash)
}
log.Info("Enqueued transaction", "hash", hash.String(), "from", from, "to", tx.To(), "isFrom pending", !addAll)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
log.Info("Enqueued transaction", "hash", hash.String(), "from", from, "to", tx.To(), "isFrom pending", !addAll)
log.Info("Enqueued transaction", "hash", hash.String(), "from", from, "to", tx.To(), "new tx", !addAll)

if addAll {
pool.all.Add(tx, local)
pool.priced.Put(tx, local)
Expand Down Expand Up @@ -975,6 +977,7 @@ func (pool *TxPool) promoteTx(addr common.Address, hash common.Hash, tx *types.T
// Nothing was replaced, bump the pending counter
pendingGauge.Inc(1)
}
log.Info("Promoted transaction from queue to pending", "hash", hash.String(), "from", addr, "to", tx.To())
// Set the potentially new pending nonce and notify any subsystems of the new tx
pool.pendingNonces.set(addr, tx.Nonce()+1)

Expand Down Expand Up @@ -1146,6 +1149,9 @@ func (pool *TxPool) removeTx(hash common.Hash, outofbound bool) {
if tx == nil {
return
}

log.Info("remove tx", "hash", hash, "outofbound", outofbound)

addr, _ := types.Sender(pool.signer, tx) // already validated during insertion

// Remove it from the list of known transactions
Expand Down Expand Up @@ -1767,6 +1773,9 @@ func (pool *TxPool) calculateTxsLifecycle(txs types.Transactions, t time.Time) {
for _, tx := range txs {
if tx.Time().Before(t) {
txLifecycle := t.Sub(tx.Time())
if txLifecycle >= time.Minute*30 {
log.Warn("calculate tx life cycle, cost over 30 minutes", "tx", tx.Hash().String())
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

may also print the time of txLifecycle.

}
txLifecycleTimer.Update(txLifecycle)
}
}
Expand Down
2 changes: 1 addition & 1 deletion params/version.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,7 @@ import (
const (
VersionMajor = 5 // Major version component of the current release
VersionMinor = 7 // Minor version component of the current release
VersionPatch = 17 // Patch version component of the current release
VersionPatch = 18 // Patch version component of the current release
VersionMeta = "mainnet" // Version metadata to append to the version string
)

Expand Down