Skip to content

Commit

Permalink
feat: show async calls and pubsub in traces
Browse files Browse the repository at this point in the history
  • Loading branch information
wesbillman committed Nov 6, 2024
1 parent 7e8abfa commit b3875e4
Show file tree
Hide file tree
Showing 18 changed files with 261 additions and 66 deletions.
1 change: 1 addition & 0 deletions backend/controller/console/console.go
Original file line number Diff line number Diff line change
Expand Up @@ -820,6 +820,7 @@ func eventDALToProto(event timeline.Event) *pbconsole.Event {
AsyncExecute: &pbconsole.AsyncExecuteEvent{
DeploymentKey: event.DeploymentKey.String(),
RequestKey: requestKey,
TimeStamp: timestamppb.New(event.Time),
AsyncEventType: asyncEventType,
VerbRef: &schemapb.Ref{
Module: event.Verb.Module,
Expand Down
17 changes: 12 additions & 5 deletions backend/controller/timeline/internal/timeline_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -112,9 +112,9 @@ func TestTimeline(t *testing.T) {
ingressEvent := &timeline2.IngressEvent{
DeploymentKey: deploymentKey,
RequestKey: optional.Some(requestKey),
Verb: schema.Ref{Module: "echo", Name: "echo"},
Verb: schema.Ref{Module: "time", Name: "time"},
Method: "GET",
Path: "/echo",
Path: "/time",
StatusCode: 200,
Time: time.Now().Round(time.Millisecond),
Request: []byte(`{"request":"body"}`),
Expand Down Expand Up @@ -264,13 +264,20 @@ func TestTimeline(t *testing.T) {
})

t.Run("ByModule", func(t *testing.T) {
events, err := timeline.QueryTimeline(ctx, 1000, timeline2.FilterTypes(timeline2.EventTypeIngress), timeline2.FilterModule("echo", optional.None[string]()))
eventTypes := []timeline2.EventType{
timeline2.EventTypeCall,
timeline2.EventTypeIngress,
timeline2.EventTypeAsyncExecute,
timeline2.EventTypePubSubPublish,
timeline2.EventTypePubSubConsume,
}
events, err := timeline.QueryTimeline(ctx, 1000, timeline2.FilterTypes(eventTypes...), timeline2.FilterModule("time", optional.None[string]()))
assert.NoError(t, err)
assertEventsEqual(t, []timeline2.Event{ingressEvent}, events)
assertEventsEqual(t, []timeline2.Event{callEvent, ingressEvent, asyncEvent, pubSubPublishEvent, pubSubConsumeEvent}, events)
})

t.Run("ByModuleWithVerb", func(t *testing.T) {
events, err := timeline.QueryTimeline(ctx, 1000, timeline2.FilterTypes(timeline2.EventTypeIngress), timeline2.FilterModule("echo", optional.Some("echo")))
events, err := timeline.QueryTimeline(ctx, 1000, timeline2.FilterTypes(timeline2.EventTypeIngress), timeline2.FilterModule("time", optional.Some("time")))
assert.NoError(t, err)
assertEventsEqual(t, []timeline2.Event{ingressEvent}, events)
})
Expand Down
27 changes: 22 additions & 5 deletions backend/controller/timeline/query.go
Original file line number Diff line number Diff line change
Expand Up @@ -224,11 +224,28 @@ func (s *Service) QueryTimeline(ctx context.Context, limit int, filters ...Timel
q += " OR "
}
if verb, ok := module.verb.Get(); ok {
q += fmt.Sprintf("((e.type = 'call' AND e.custom_key_3 = $%d AND e.custom_key_4 = $%d) OR (e.type = 'ingress' AND e.custom_key_1 = $%d AND e.custom_key_2 = $%d))",
param(module.module), param(verb), param(module.module), param(verb))
q += fmt.Sprintf(
"((e.type = 'call' AND e.custom_key_3 = $%d AND e.custom_key_4 = $%d) OR "+
"(e.type = 'ingress' AND e.custom_key_1 = $%d AND e.custom_key_2 = $%d) OR "+
"(e.type = 'async_execute' AND e.custom_key_1 = $%d AND e.custom_key_2 = $%d) OR "+
"(e.type = 'pubsub_publish' AND e.custom_key_1 = $%d AND e.custom_key_2 = $%d) OR "+
"(e.type = 'pubsub_consume' AND e.custom_key_1 = $%d AND e.custom_key_2 = $%d))",
param(module.module), param(verb),
param(module.module), param(verb),
param(module.module), param(verb),
param(module.module), param(verb),
param(module.module), param(verb),
)
} else {
q += fmt.Sprintf("((e.type = 'call' AND e.custom_key_3 = $%d) OR (e.type = 'ingress' AND e.custom_key_1 = $%d))",
param(module.module), param(module.module))
q += fmt.Sprintf(
"((e.type = 'call' AND e.custom_key_3 = $%d) OR "+
"(e.type = 'ingress' AND e.custom_key_1 = $%d) OR "+
"(e.type = 'async_execute' AND e.custom_key_1 = $%d) OR "+
"(e.type = 'pubsub_publish' AND e.custom_key_1 = $%d) OR "+
"(e.type = 'pubsub_consume' AND e.custom_key_1 = $%d))",
param(module.module), param(module.module), param(module.module),
param(module.module), param(module.module),
)
}
}
q += ")\n"
Expand Down Expand Up @@ -454,7 +471,7 @@ func (s *Service) transformRowsToTimelineEvents(deploymentKeys map[int64]model.D
}
out = append(out, &PubSubConsumeEvent{
ID: row.ID,
Duration: time.Since(row.TimeStamp),
Duration: time.Duration(jsonPayload.DurationMS) * time.Millisecond,
PubSubConsume: PubSubConsume{
DeploymentKey: row.DeploymentKey,
RequestKey: requestKey,
Expand Down
26 changes: 22 additions & 4 deletions frontend/console/src/api/timeline/use-request-trace-events.ts
Original file line number Diff line number Diff line change
@@ -1,15 +1,33 @@
import { type CallEvent, EventType, type EventsQuery_Filter, type IngressEvent } from '../../protos/xyz/block/ftl/v1/console/console_pb.ts'
import {
type AsyncExecuteEvent,
type CallEvent,
EventType,
type EventsQuery_Filter,
type IngressEvent,
type PubSubConsumeEvent,
type PubSubPublishEvent,
} from '../../protos/xyz/block/ftl/v1/console/console_pb.ts'
import { eventTypesFilter, requestKeysFilter } from './timeline-filters.ts'
import { useTimeline } from './use-timeline.ts'

export type TraceEvent = CallEvent | IngressEvent
export type TraceEvent = CallEvent | IngressEvent | AsyncExecuteEvent | PubSubPublishEvent | PubSubConsumeEvent

export const useRequestTraceEvents = (requestKey?: string, filters: EventsQuery_Filter[] = []) => {
const eventTypes = [EventType.CALL, EventType.INGRESS]
const eventTypes = [EventType.CALL, EventType.ASYNC_EXECUTE, EventType.INGRESS, EventType.PUBSUB_CONSUME, EventType.PUBSUB_PUBLISH]

const allFilters = [...filters, requestKeysFilter([requestKey || '']), eventTypesFilter(eventTypes)]
const timelineQuery = useTimeline(true, allFilters, 500, !!requestKey)

const data = timelineQuery.data?.filter((event) => event.entry.case === 'call' || event.entry.case === 'ingress') ?? []
const data =
timelineQuery.data?.filter(
(event) =>
event.entry.case === 'call' ||
event.entry.case === 'ingress' ||
event.entry.case === 'asyncExecute' ||
event.entry.case === 'pubsubPublish' ||
event.entry.case === 'pubsubConsume',
) ?? []

return {
...timelineQuery,
data,
Expand Down
4 changes: 2 additions & 2 deletions frontend/console/src/features/modules/ModulesTree.tsx
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
import { ArrowRight01Icon, ArrowShrink02Icon, CircleArrowRight02Icon, PackageIcon, Upload01Icon } from 'hugeicons-react'
import { ArrowRight01Icon, ArrowShrink02Icon, CircleArrowRight02Icon, CodeFolderIcon, Upload01Icon } from 'hugeicons-react'
import { useEffect, useMemo, useRef, useState } from 'react'
import { Link, useParams, useSearchParams } from 'react-router-dom'
import { Multiselect, sortMultiselectOpts } from '../../components/Multiselect'
Expand Down Expand Up @@ -99,7 +99,7 @@ const ModuleSection = ({
onClick={() => toggleExpansion(module.name)}
>
<span title='module'>
<PackageIcon aria-hidden='true' className='size-4 my-1 ml-3 shrink-0' />
<CodeFolderIcon aria-hidden='true' className='size-4 my-1 ml-3 shrink-0' />
</span>
{module.name}
<Link to={`/modules/${module.name}`} onClick={(e) => e.stopPropagation()}>
Expand Down
3 changes: 2 additions & 1 deletion frontend/console/src/features/modules/module.utils.ts
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@ import {
BubbleChatIcon,
Clock01Icon,
CodeIcon,
CodeSquareIcon,
DatabaseIcon,
FunctionIcon,
type HugeiconsProps,
Expand Down Expand Up @@ -186,7 +187,7 @@ export const declTypeName = (declCase: string, decl: DeclSumType) => {

const declIcons: Record<string, React.FC<Omit<HugeiconsProps, 'ref'> & React.RefAttributes<SVGSVGElement>>> = {
config: Settings02Icon,
data: CodeIcon,
data: CodeSquareIcon,
database: DatabaseIcon,
enum: LeftToRightListNumberIcon,
topic: BubbleChatIcon,
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,8 @@ import { CodeBlock } from '../../../components/CodeBlock'
import type { AsyncExecuteEvent, Event } from '../../../protos/xyz/block/ftl/v1/console/console_pb'
import { formatDuration } from '../../../utils/date.utils'
import { DeploymentCard } from '../../deployments/DeploymentCard'
import { TraceGraph } from '../../traces/TraceGraph'
import { TraceGraphHeader } from '../../traces/TraceGraphHeader'
import { refString } from '../../verbs/verb.utils'
import { asyncEventTypeString } from '../timeline.utils'

Expand All @@ -12,16 +14,24 @@ export const TimelineAsyncExecuteDetails = ({ event }: { event: Event }) => {
return (
<>
<div className='p-4'>
<div className='pb-2'>
<TraceGraphHeader requestKey={asyncEvent.requestKey} eventId={event.id} />
<TraceGraph requestKey={asyncEvent.requestKey} selectedEventId={event.id} />
</div>

{asyncEvent.error && (
<>
<h3>Error</h3>
<CodeBlock code={asyncEvent.error} language='text' />
</>
)}

<DeploymentCard deploymentKey={asyncEvent.deploymentKey} />

<ul className='pt-4 space-y-2'>
{asyncEvent.requestKey && (
<li>
<AttributeBadge name='request' value={asyncEvent.requestKey} />
</li>
)}
<li>
<AttributeBadge name='duration' value={formatDuration(asyncEvent.duration)} />
</li>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,12 @@ export const TimelinePubSubConsumeDetails = ({ event }: { event: Event }) => {
<DeploymentCard className='mt-4' deploymentKey={pubSubConsume.deploymentKey} />

<ul className='pt-4 space-y-2'>
{pubSubConsume.requestKey && (
<li>
<AttributeBadge name='request' value={pubSubConsume.requestKey} />
</li>
)}

<li>
<AttributeBadge name='sink' value={destModule} />
</li>
Expand Down
3 changes: 3 additions & 0 deletions frontend/console/src/features/timeline/timeline.utils.ts
Original file line number Diff line number Diff line change
Expand Up @@ -59,5 +59,8 @@ const isError = (event: Event) => {
if (event.entry.case === 'ingress' && event.entry.value.error) {
return true
}
if (event.entry.case === 'asyncExecute' && event.entry.value.error) {
return true
}
return false
}
11 changes: 8 additions & 3 deletions frontend/console/src/features/traces/TraceDetailItem.tsx
Original file line number Diff line number Diff line change
@@ -1,6 +1,5 @@
import type { Timestamp } from '@bufbuild/protobuf'
import type { TraceEvent } from '../../api/timeline/use-request-trace-events'
import { CallEvent, type Event, IngressEvent } from '../../protos/xyz/block/ftl/v1/console/console_pb'
import { AsyncExecuteEvent, CallEvent, type Event, IngressEvent, PubSubPublishEvent } from '../../protos/xyz/block/ftl/v1/console/console_pb'
import { classNames } from '../../utils'
import { TimelineIcon } from '../timeline/TimelineIcon'
import { eventBackgroundColor } from '../timeline/timeline.utils'
Expand All @@ -11,7 +10,7 @@ interface TraceDetailItemProps {
traceEvent: TraceEvent
eventDurationMs: number
requestDurationMs: number
requestStartTime: Timestamp | undefined
requestStartTime: number
selectedEventId: bigint | undefined
handleEventClick: (eventId: bigint) => void
}
Expand Down Expand Up @@ -40,6 +39,12 @@ export const TraceDetailItem: React.FC<TraceDetailItemProps> = ({
} else if (traceEvent instanceof IngressEvent) {
action = `HTTP ${traceEvent.method}`
eventName = `${traceEvent.path}`
} else if (traceEvent instanceof AsyncExecuteEvent) {
action = 'Async'
eventName = `${traceEvent.verbRef?.module}.${traceEvent.verbRef?.name}`
} else if (traceEvent instanceof PubSubPublishEvent) {
action = 'Publish'
eventName = `${traceEvent.topic}`
}

const barColor = event.id === selectedEventId ? 'bg-green-500' : eventBackgroundColor(event)
Expand Down
19 changes: 13 additions & 6 deletions frontend/console/src/features/traces/TraceDetails.tsx
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@ import type React from 'react'
import { useNavigate } from 'react-router-dom'
import type { TraceEvent } from '../../api/timeline/use-request-trace-events'
import type { Event } from '../../protos/xyz/block/ftl/v1/console/console_pb'
import { durationToMillis } from '../../utils'
import { TraceDetailItem } from './TraceDetailItem'

interface TraceDetailsProps {
Expand All @@ -13,9 +14,15 @@ interface TraceDetailsProps {
export const TraceDetails: React.FC<TraceDetailsProps> = ({ events, selectedEventId, requestKey }) => {
const navigate = useNavigate()

const requestStartTime = events[0]?.timeStamp
const firstEvent = events[0].entry.value as TraceEvent
const requestDurationMs = (firstEvent?.duration?.nanos ?? 0) / 1000000
const traceEvents = events.map((event) => event.entry.value as TraceEvent)
const requestStartTime = Math.min(...traceEvents.map((event) => event.timeStamp?.toDate().getTime() ?? 0))
const requestEndTime = Math.max(
...traceEvents.map((event) => {
const eventDuration = event.duration ? durationToMillis(event.duration) : 0
return (event.timeStamp?.toDate().getTime() ?? 0) + eventDuration
}),
)
const totalEventDuration = requestEndTime - requestStartTime

const handleEventClick = (eventId: bigint) => {
navigate(`/traces/${requestKey}?event_id=${eventId}`)
Expand All @@ -25,10 +32,10 @@ export const TraceDetails: React.FC<TraceDetailsProps> = ({ events, selectedEven
<div>
<div className='mb-6 p-4 bg-gray-50 dark:bg-gray-700 rounded-lg shadow-sm'>
<h2 className='font-semibold text-lg text-gray-800 dark:text-gray-100 mb-2'>
Total Duration: <span className='font-bold text-indigo-600 dark:text-indigo-400'>{requestDurationMs} ms</span>
Total Duration: <span className='font-bold text-indigo-600 dark:text-indigo-400'>{totalEventDuration} ms</span>
</h2>
<p className='text-sm text-gray-600 dark:text-gray-300'>
Start Time: <span className='text-gray-800 dark:text-gray-100'>{requestStartTime?.toDate().toLocaleString()}</span>
Start Time: <span className='text-gray-800 dark:text-gray-100'>{new Date(requestStartTime).toLocaleString()}</span>
</p>
</div>

Expand All @@ -43,7 +50,7 @@ export const TraceDetails: React.FC<TraceDetailsProps> = ({ events, selectedEven
event={event}
traceEvent={traceEvent}
eventDurationMs={eventDurationMs}
requestDurationMs={requestDurationMs}
requestDurationMs={totalEventDuration}
requestStartTime={requestStartTime}
selectedEventId={selectedEventId}
handleEventClick={handleEventClick}
Expand Down
55 changes: 37 additions & 18 deletions frontend/console/src/features/traces/TraceGraph.tsx
Original file line number Diff line number Diff line change
@@ -1,8 +1,14 @@
import type { Duration, Timestamp } from '@bufbuild/protobuf'
import { useState } from 'react'
import { type TraceEvent, useRequestTraceEvents } from '../../api/timeline/use-request-trace-events'
import { CallEvent, type Event, IngressEvent } from '../../protos/xyz/block/ftl/v1/console/console_pb'
import { classNames } from '../../utils'
import {
AsyncExecuteEvent,
CallEvent,
type Event,
IngressEvent,
PubSubConsumeEvent,
PubSubPublishEvent,
} from '../../protos/xyz/block/ftl/v1/console/console_pb'
import { classNames, durationToMillis } from '../../utils'
import { eventBackgroundColor } from '../timeline/timeline.utils'
import { eventBarLeftOffsetPercentage } from './traces.utils'

Expand All @@ -14,27 +20,38 @@ const EventBlock = ({
}: {
event: Event
isSelected: boolean
requestStartTime: Timestamp
requestDuration: Duration
requestStartTime: number
requestDuration: number
}) => {
const [isHovering, setIsHovering] = useState(false)

const traceEvent = event.entry.value as TraceEvent
const totalDurationMillis = (requestDuration.nanos ?? 0) / 1000000
const durationInMillis = (traceEvent.duration?.nanos ?? 0) / 1000000
let width = (durationInMillis / totalDurationMillis) * 100
const durationInMillis = traceEvent.duration ? durationToMillis(traceEvent.duration) : 0
let width = (durationInMillis / requestDuration) * 100
if (width < 1) {
width = 1
}

const leftOffsetPercentage = eventBarLeftOffsetPercentage(event, requestStartTime, totalDurationMillis)
const leftOffsetPercentage = eventBarLeftOffsetPercentage(event, requestStartTime, requestDuration)

let eventType = ''
let eventTarget = ''

if (traceEvent instanceof CallEvent) {
eventType = 'call'
eventTarget = `${traceEvent.destinationVerbRef?.module}.${traceEvent.destinationVerbRef?.name}`
} else if (traceEvent instanceof IngressEvent) {
eventType = 'ingress'
eventTarget = traceEvent.path
} else if (traceEvent instanceof AsyncExecuteEvent) {
eventType = 'async'
eventTarget = `${traceEvent.verbRef?.module}.${traceEvent.verbRef?.name}`
} else if (traceEvent instanceof PubSubPublishEvent) {
eventType = 'publish'
eventTarget = traceEvent.topic
} else if (traceEvent instanceof PubSubConsumeEvent) {
eventType = 'consume'
eventTarget = traceEvent.topic
}

const barColor = isSelected ? 'bg-green-500' : eventBackgroundColor(event)
Expand All @@ -52,8 +69,7 @@ const EventBlock = ({
{isHovering && (
<div className='absolute top-[-40px] right-0 bg-gray-100 dark:bg-gray-700 text-xs p-2 rounded shadow-lg z-10 w-max flex flex-col items-end'>
<p>
{event instanceof CallEvent ? 'Call ' : 'Ingress '}
<span className='text-indigo-500 dark:text-indigo-400'>{eventTarget}</span>
{eventType} <span className='text-indigo-500 dark:text-indigo-400'>{eventTarget}</span>
{` (${durationInMillis} ms)`}
</p>
</div>
Expand All @@ -71,19 +87,22 @@ export const TraceGraph = ({ requestKey, selectedEventId }: { requestKey?: strin
return
}

const requestStartTime = events[0].timeStamp
const traceEvent = events[0].entry.value as TraceEvent
const firstEventDuration = traceEvent.duration
if (requestStartTime === undefined || firstEventDuration === undefined) {
return
}
const traceEvents = events.map((event) => event.entry.value as TraceEvent)
const requestStartTime = Math.min(...traceEvents.map((event) => event.timeStamp?.toDate().getTime() ?? 0))
const requestEndTime = Math.max(
...traceEvents.map((event) => {
const eventDuration = event.duration ? durationToMillis(event.duration) : 0
return (event.timeStamp?.toDate().getTime() ?? 0) + eventDuration
}),
)
const totalEventDuration = requestEndTime - requestStartTime

return (
<div className='flex flex-col'>
{events.map((c, index) => (
<div key={index} className='flex hover:bg-indigo-500/60 hover:dark:bg-indigo-500/10 rounded-sm'>
<div className='w-full relative'>
<EventBlock event={c} isSelected={c.id === selectedEventId} requestStartTime={requestStartTime} requestDuration={firstEventDuration} />
<EventBlock event={c} isSelected={c.id === selectedEventId} requestStartTime={requestStartTime} requestDuration={totalEventDuration} />
</div>
</div>
))}
Expand Down
Loading

0 comments on commit b3875e4

Please sign in to comment.