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

Record and log additional metrics for O #1670

Merged
merged 5 commits into from
Nov 27, 2020
Merged

Record and log additional metrics for O #1670

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
82fca25
cmd+monitor: NodeType type instead of string
yondonfu Nov 26, 2020
35f7696
server: Record & log source & dl dur
yondonfu Nov 25, 2020
0b492ac
monitor: Tweak dist for source seg dur
yondonfu Nov 26, 2020
39b267c
monitor: Broadcaster only logic in SegmentEmerged
yondonfu Nov 26, 2020
d3c2106
monitor+core+server: Record transcode score
yondonfu Nov 26, 2020
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
10 changes: 5 additions & 5 deletions cmd/livepeer/livepeer.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -313,16 +313,16 @@ func main() {

if *monitor {
lpmon.Enabled = true
nodeType := "dflt"
nodeType := lpmon.Default
switch n.NodeType {
case core.BroadcasterNode:
nodeType = "bctr"
nodeType = lpmon.Broadcaster
case core.OrchestratorNode:
nodeType = "orch"
nodeType = lpmon.Orchestrator
case core.TranscoderNode:
nodeType = "trcr"
nodeType = lpmon.Transcoder
case core.RedeemerNode:
nodeType = "rdmr"
nodeType = lpmon.Redeemer
}
lpmon.InitCensus(nodeType, core.LivepeerVersion)
}
Expand Down
2 changes: 1 addition & 1 deletion core/orchestrator.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -554,7 +554,7 @@ func (n *LivepeerNode) transcodeSeg(config transcodeConfig, seg *stream.HLSSegme
took := time.Since(start)
glog.V(common.DEBUG).Infof("Transcoding of segment manifestID=%s sessionID=%s seqNo=%d took=%v", string(md.ManifestID), md.AuthToken.SessionId, seg.SeqNo, took)
if monitor.Enabled {
monitor.SegmentTranscoded(0, seg.SeqNo, took, common.ProfilesNames(md.Profiles))
monitor.SegmentTranscoded(0, seg.SeqNo, md.Duration, took, common.ProfilesNames(md.Profiles))
}

// Prepare the result object
Expand Down
4 changes: 2 additions & 2 deletions core/transcoder.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -51,7 +51,7 @@ func (lt *LocalTranscoder) Transcode(md *SegTranscodingMetadata) (*TranscodeData
// When orchestrator works as transcoder, `fname` will be relative path to file in local
// filesystem and will not contain seqNo in it. For that case `SegmentTranscoded` will
// be called in orchestrator.go
monitor.SegmentTranscoded(0, seqNo, time.Since(start), common.ProfilesNames(profiles))
monitor.SegmentTranscoded(0, seqNo, md.Duration, time.Since(start), common.ProfilesNames(profiles))
}

return resToTranscodeData(res, opts)
Expand Down Expand Up @@ -89,7 +89,7 @@ func (nv *NvidiaTranscoder) Transcode(md *SegTranscodingMetadata) (*TranscodeDat
// When orchestrator works as transcoder, `fname` will be relative path to file in local
// filesystem and will not contain seqNo in it. For that case `SegmentTranscoded` will
// be called in orchestrator.go
monitor.SegmentTranscoded(0, seqNo, time.Since(start), common.ProfilesNames(profiles))
monitor.SegmentTranscoded(0, seqNo, md.Duration, time.Since(start), common.ProfilesNames(profiles))
}

return resToTranscodeData(res, out)
Expand Down
43 changes: 32 additions & 11 deletions monitor/census.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -50,6 +50,16 @@ const (
// importing `common` package here introduces import cycles
)

type NodeType string

const (
Default NodeType = "dflt"
Orchestrator NodeType = "orch"
Broadcaster NodeType = "bctr"
Transcoder NodeType = "trcr"
Redeemer NodeType = "rdmr"
)

// Enabled true if metrics was enabled in command line
var Enabled bool

Expand All @@ -60,7 +70,7 @@ var timeoutWatcherPause = 15 * time.Second

type (
censusMetricsCounter struct {
nodeType string
nodeType NodeType
nodeID string
ctx context.Context
kGPU tag.Key
Expand Down Expand Up @@ -111,6 +121,7 @@ type (
mRealtime1x *stats.Int64Measure
mRealtimeHalf *stats.Int64Measure
mRealtimeSlow *stats.Int64Measure
mTranscodeScore *stats.Float64Measure

// Metrics for sending payments
mTicketValueSent *stats.Float64Measure
Expand Down Expand Up @@ -165,7 +176,7 @@ var census censusMetricsCounter
// used in unit tests
var unitTestMode bool

func InitCensus(nodeType, version string) {
func InitCensus(nodeType NodeType, version string) {
census = censusMetricsCounter{
emergeTimes: make(map[uint64]map[uint64]time.Time),
nodeID: NodeID,
Expand All @@ -184,7 +195,7 @@ func InitCensus(nodeType, version string) {
census.kSender = tag.MustNewKey("sender")
census.kRecipient = tag.MustNewKey("recipient")
census.kManifestID = tag.MustNewKey("manifestID")
census.ctx, err = tag.New(ctx, tag.Insert(census.kNodeType, nodeType), tag.Insert(census.kNodeID, NodeID))
census.ctx, err = tag.New(ctx, tag.Insert(census.kNodeType, string(nodeType)), tag.Insert(census.kNodeID, NodeID))
if err != nil {
glog.Fatal("Error creating context", err)
}
Expand Down Expand Up @@ -228,6 +239,7 @@ func InitCensus(nodeType, version string) {
census.mDownloadTime = stats.Float64("download_time_seconds", "Download (from orchestrator) time", "sec")
census.mAuthWebhookTime = stats.Float64("auth_webhook_time_milliseconds", "Authentication webhook execution time", "ms")
census.mSourceSegmentDuration = stats.Float64("source_segment_duration_seconds", "Source segment's duration", "sec")
census.mTranscodeScore = stats.Float64("transcode_score", "Ratio of source segment duration vs. transcode time", "rat")

// Metrics for sending payments
census.mTicketValueSent = stats.Float64("ticket_value_sent", "TicketValueSent", "gwei")
Expand Down Expand Up @@ -255,7 +267,7 @@ func InitCensus(nodeType, version string) {
goos := tag.MustNewKey("goos")
goversion := tag.MustNewKey("goversion")
livepeerversion := tag.MustNewKey("livepeerversion")
ctx, err = tag.New(ctx, tag.Insert(census.kNodeType, nodeType), tag.Insert(census.kNodeID, NodeID),
ctx, err = tag.New(ctx, tag.Insert(census.kNodeType, string(nodeType)), tag.Insert(census.kNodeID, NodeID),
tag.Insert(compiler, runtime.Compiler), tag.Insert(goarch, runtime.GOARCH), tag.Insert(goos, runtime.GOOS),
tag.Insert(goversion, runtime.Version()), tag.Insert(livepeerversion, version))
if err != nil {
Expand Down Expand Up @@ -459,6 +471,13 @@ func InitCensus(nodeType, version string) {
TagKeys: append([]tag.Key{census.kProfiles}, baseTags...),
Aggregation: view.Distribution(0, .500, .75, 1.000, 1.500, 2.000, 2.500, 3.000, 3.500, 4.000, 4.500, 5.000, 10.000),
},
{
Name: "transcode_score",
Measure: census.mTranscodeScore,
Description: "Ratio of source segment duration vs. transcode time",
TagKeys: append([]tag.Key{census.kProfiles}, baseTags...),
Aggregation: view.Distribution(0, .25, .5, .75, 1, 1.25, 1.5, 1.75, 2, 2.25, 2.5, 2.75, 3, 3.25, 3.5, 3.75, 4),
},
{
Name: "upload_time_seconds",
Measure: census.mUploadTime,
Expand All @@ -469,7 +488,7 @@ func InitCensus(nodeType, version string) {
{
Name: "download_time_seconds",
Measure: census.mDownloadTime,
Description: "Download (from orchestrator) time",
Description: "Download time",
TagKeys: baseTags,
Aggregation: view.Distribution(0, .10, .20, .50, .100, .150, .200, .500, .1000, .5000, 10.000),
},
Expand All @@ -485,7 +504,7 @@ func InitCensus(nodeType, version string) {
Measure: census.mSourceSegmentDuration,
Description: "Source segment's duration",
TagKeys: baseTags,
Aggregation: view.Distribution(0, 100, 250, 500, 750, 1000, 1500, 2000, 2500, 3000, 5000, 10000, 20000, 30000),
Aggregation: view.Distribution(0, .5, 1, 1.5, 2, 2.5, 3, 3.5, 4, 4.5, 5, 10, 15, 20),
},
{
Name: "max_sessions_total",
Expand Down Expand Up @@ -881,7 +900,9 @@ func SetTranscodersNumberAndLoad(load, capacity, number int) {

func SegmentEmerged(nonce, seqNo uint64, profilesNum int, dur float64) {
glog.V(logLevel).Infof("Logging SegmentEmerged... nonce=%d seqNo=%d duration=%v", nonce, seqNo, dur)
census.segmentEmerged(nonce, seqNo, profilesNum)
if census.nodeType == Broadcaster {
census.segmentEmerged(nonce, seqNo, profilesNum)
}
stats.Record(census.ctx, census.mSourceSegmentDuration.M(dur))
}

Expand Down Expand Up @@ -1000,12 +1021,12 @@ func (cen *censusMetricsCounter) segmentUploadFailed(nonce, seqNo uint64, code S
}
}

func SegmentTranscoded(nonce, seqNo uint64, transcodeDur time.Duration, profiles string) {
func SegmentTranscoded(nonce, seqNo uint64, sourceDur time.Duration, transcodeDur time.Duration, profiles string) {
glog.V(logLevel).Infof("Logging SegmentTranscode nonce=%d seqNo=%d dur=%s", nonce, seqNo, transcodeDur)
census.segmentTranscoded(nonce, seqNo, transcodeDur, profiles)
census.segmentTranscoded(nonce, seqNo, sourceDur, transcodeDur, profiles)
}

func (cen *censusMetricsCounter) segmentTranscoded(nonce, seqNo uint64, transcodeDur time.Duration,
func (cen *censusMetricsCounter) segmentTranscoded(nonce, seqNo uint64, sourceDur time.Duration, transcodeDur time.Duration,
profiles string) {
cen.lock.Lock()
defer cen.lock.Unlock()
Expand All @@ -1014,7 +1035,7 @@ func (cen *censusMetricsCounter) segmentTranscoded(nonce, seqNo uint64, transcod
glog.Error("Error creating context", err)
return
}
stats.Record(ctx, cen.mSegmentTranscoded.M(1), cen.mTranscodeTime.M(transcodeDur.Seconds()))
stats.Record(ctx, cen.mSegmentTranscoded.M(1), cen.mTranscodeTime.M(transcodeDur.Seconds()), cen.mTranscodeScore.M(sourceDur.Seconds()/transcodeDur.Seconds()))
}

func SegmentTranscodeFailed(subType SegmentTranscodeError, nonce, seqNo uint64, err error, permanent bool) {
Expand Down
2 changes: 1 addition & 1 deletion monitor/census_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -49,7 +49,7 @@ func TestLastSegmentTimeout(t *testing.T) {
defer func() { unitTestMode = false }()
NodeID = "testid"

InitCensus("tst", "testversion")
InitCensus("bctr", "testversion")
// defer func() {
// shutDown <- nil
// }()
Expand Down
16 changes: 15 additions & 1 deletion server/segment_rpc.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -80,6 +80,12 @@ func (h *lphttp) ServeSegment(w http.ResponseWriter, r *http.Request) {
return
}

glog.V(common.VERBOSE).Infof("Received segment manifestID=%s sessionID=%s seqNo=%d dur=%v", segData.ManifestID, segData.AuthToken.SessionId, segData.Seq, segData.Duration)

if monitor.Enabled {
monitor.SegmentEmerged(0, uint64(segData.Seq), len(segData.Profiles), segData.Duration.Seconds())
}

if err := orch.ProcessPayment(payment, core.ManifestID(segData.AuthToken.SessionId)); err != nil {
glog.Errorf("error processing payment: %v", err)
http.Error(w, err.Error(), http.StatusBadRequest)
Expand All @@ -105,13 +111,21 @@ func (h *lphttp) ServeSegment(w http.ResponseWriter, r *http.Request) {
oInfo.AuthToken = segData.AuthToken

// download the segment and check the hash
dlStart := time.Now()
data, err := ioutil.ReadAll(r.Body)
if err != nil {
glog.Errorf("Could not read request body - err=%v", err)
http.Error(w, "Internal Server Error", http.StatusInternalServerError)
return
}

dlDur := time.Since(dlStart)
glog.V(common.VERBOSE).Infof("Downloaded segment manifestID=%s sessionID=%s seqNo=%d dur=%v", segData.ManifestID, segData.AuthToken.SessionId, segData.Seq, dlDur)

if monitor.Enabled {
monitor.SegmentDownloaded(0, uint64(segData.Seq), dlDur)
}

uri := ""
if r.Header.Get("Content-Type") == "application/vnd+livepeer.uri" {
uri = string(data)
Expand Down Expand Up @@ -518,7 +532,7 @@ func SubmitSegment(sess *BroadcastSession, seg *stream.HLSSegment, nonce uint64)

// transcode succeeded; continue processing response
if monitor.Enabled {
monitor.SegmentTranscoded(nonce, seg.SeqNo, transcodeDur, common.ProfilesNames(params.Profiles))
monitor.SegmentTranscoded(nonce, seg.SeqNo, time.Duration(seg.Duration*float64(time.Second)), transcodeDur, common.ProfilesNames(params.Profiles))
}

glog.Infof("Successfully transcoded segment nonce=%d manifestID=%s sessionID=%s segName=%s seqNo=%d orch=%s dur=%s", nonce,
Expand Down