Child span ends later than parent span

[tuhao1020]

As shown in the figure below, the child span() ends later than the parent span(), is this a bug?

{
    "data": [
        {
            "traceID": "96be510babcc56f2a97085cc379a9f83",
            "spans": [
                {
                    "traceID": "96be510babcc56f2a97085cc379a9f83",
                    "spanID": "617069213aadca5e",
                    "operationName": "http get",
                    "references": [
                        {
                            "refType": "CHILD_OF",
                            "traceID": "96be510babcc56f2a97085cc379a9f83",
                            "spanID": "d8abaf0e6598453d"
                        }
                    ],
                    "startTime": 1654001468987144,
                    "duration": 6191,
                    "tags": [
                        {
                            "key": "http.url",
                            "type": "string",
                            "value": "http://localhost:8080/hello"
                        },
                        {
                            "key": "thread.id",
                            "type": "string",
                            "value": "39"
                        },
                        {
                            "key": "http.status_code",
                            "type": "string",
                            "value": "200"
                        },
                        {
                            "key": "key2",
                            "type": "string",
                            "value": "value2"
                        },
                        {
                            "key": "net.peer.name",
                            "type": "string",
                            "value": "localhost"
                        },
                        {
                            "key": "net.peer.port",
                            "type": "string",
                            "value": "8080"
                        },
                        {
                            "key": "otel.scope.name",
                            "type": "string",
                            "value": "io.opentelemetry.http-url-connection"
                        },
                        {
                            "key": "otel.scope.version",
                            "type": "string",
                            "value": "1.14.0-alpha-SNAPSHOT"
                        },
                        {
                            "key": "http.flavor",
                            "type": "string",
                            "value": "1.1"
                        },
                        {
                            "key": "http.method",
                            "type": "string",
                            "value": "GET"
                        },
                        {
                            "key": "net.transport",
                            "type": "string",
                            "value": "ip_tcp"
                        },
                        {
                            "key": "ns",
                            "type": "string",
                            "value": "tuhao-1"
                        },
                        {
                            "key": "otel.library.name",
                            "type": "string",
                            "value": "io.opentelemetry.http-url-connection"
                        },
                        {
                            "key": "otel.library.version",
                            "type": "string",
                            "value": "1.14.0-alpha-SNAPSHOT"
                        },
                        {
                            "key": "thread.name",
                            "type": "string",
                            "value": "http-nio-8081-exec-7"
                        },
                        {
                            "key": "clusterID",
                            "type": "string",
                            "value": "dev"
                        },
                        {
                            "key": "span.kind",
                            "type": "string",
                            "value": "client"
                        },
                        {
                            "key": "internal.span.format",
                            "type": "string",
                            "value": "zipkin"
                        }
                    ],
                    "logs": [],
                    "processID": "p1",
                    "warnings": null
                },
                {
                    "traceID": "96be510babcc56f2a97085cc379a9f83",
                    "spanID": "d8abaf0e6598453d",
                    "operationName": "controller.hello",
                    "references": [
                        {
                            "refType": "CHILD_OF",
                            "traceID": "96be510babcc56f2a97085cc379a9f83",
                            "spanID": "fba3967d0e1558f9"
                        }
                    ],
                    "startTime": 1654001468986596,
                    "duration": 9740,
                    "tags": [
                        {
                            "key": "ns",
                            "type": "string",
                            "value": "tuhao-1"
                        },
                        {
                            "key": "thread.id",
                            "type": "string",
                            "value": "39"
                        },
                        {
                            "key": "thread.name",
                            "type": "string",
                            "value": "http-nio-8081-exec-7"
                        },
                        {
                            "key": "clusterID",
                            "type": "string",
                            "value": "dev"
                        },
                        {
                            "key": "key2",
                            "type": "string",
                            "value": "value2"
                        },
                        {
                            "key": "otel.library.name",
                            "type": "string",
                            "value": "io.opentelemetry.spring-webmvc-3.1"
                        },
                        {
                            "key": "otel.library.version",
                            "type": "string",
                            "value": "1.14.0-alpha-SNAPSHOT"
                        },
                        {
                            "key": "otel.scope.name",
                            "type": "string",
                            "value": "io.opentelemetry.spring-webmvc-3.1"
                        },
                        {
                            "key": "otel.scope.version",
                            "type": "string",
                            "value": "1.14.0-alpha-SNAPSHOT"
                        },
                        {
                            "key": "internal.span.format",
                            "type": "string",
                            "value": "zipkin"
                        }
                    ],
                    "logs": [],
                    "processID": "p1",
                    "warnings": null
                },
                {
                    "traceID": "96be510babcc56f2a97085cc379a9f83",
                    "spanID": "fba3967d0e1558f9",
                    "operationName": "/hello",
                    "references": [],
                    "startTime": 1654001468985676,
                    "duration": 12010,
                    "tags": [
                        {
                            "key": "http.method",
                            "type": "string",
                            "value": "GET"
                        },
                        {
                            "key": "http.route",
                            "type": "string",
                            "value": "/hello"
                        },
                        {
                            "key": "http.user_agent",
                            "type": "string",
                            "value": "curl/7.79.1"
                        },
                        {
                            "key": "net.transport",
                            "type": "string",
                            "value": "ip_tcp"
                        },
                        {
                            "key": "thread.name",
                            "type": "string",
                            "value": "http-nio-8081-exec-7"
                        },
                        {
                            "key": "http.flavor",
                            "type": "string",
                            "value": "1.1"
                        },
                        {
                            "key": "http.scheme",
                            "type": "string",
                            "value": "http"
                        },
                        {
                            "key": "otel.library.name",
                            "type": "string",
                            "value": "io.opentelemetry.tomcat-7.0"
                        },
                        {
                            "key": "otel.library.version",
                            "type": "string",
                            "value": "1.14.0-alpha-SNAPSHOT"
                        },
                        {
                            "key": "otel.scope.name",
                            "type": "string",
                            "value": "io.opentelemetry.tomcat-7.0"
                        },
                        {
                            "key": "otel.scope.version",
                            "type": "string",
                            "value": "1.14.0-alpha-SNAPSHOT"
                        },
                        {
                            "key": "clusterID",
                            "type": "string",
                            "value": "dev"
                        },
                        {
                            "key": "http.target",
                            "type": "string",
                            "value": "/hello"
                        },
                        {
                            "key": "net.peer.port",
                            "type": "string",
                            "value": "55549"
                        },
                        {
                            "key": "ns",
                            "type": "string",
                            "value": "tuhao-1"
                        },
                        {
                            "key": "thread.id",
                            "type": "string",
                            "value": "39"
                        },
                        {
                            "key": "http.host",
                            "type": "string",
                            "value": "localhost:8081"
                        },
                        {
                            "key": "http.status_code",
                            "type": "string",
                            "value": "200"
                        },
                        {
                            "key": "key2",
                            "type": "string",
                            "value": "value2"
                        },
                        {
                            "key": "net.peer.ip",
                            "type": "string",
                            "value": "127.0.0.1"
                        },
                        {
                            "key": "http.response_content_length",
                            "type": "string",
                            "value": "23"
                        },
                        {
                            "key": "span.kind",
                            "type": "string",
                            "value": "server"
                        },
                        {
                            "key": "internal.span.format",
                            "type": "string",
                            "value": "zipkin"
                        }
                    ],
                    "logs": [],
                    "processID": "p1",
                    "warnings": null
                },
                {
                    "traceID": "96be510babcc56f2a97085cc379a9f83",
                    "spanID": "f6a0105d4ac11b1d",
                    "operationName": "controller.hello",
                    "references": [
                        {
                            "refType": "CHILD_OF",
                            "traceID": "96be510babcc56f2a97085cc379a9f83",
                            "spanID": "d5feb1703407485d"
                        }
                    ],
                    "startTime": 1654001468990277,
                    "duration": 2117,
                    "tags": [
                        {
                            "key": "key2",
                            "type": "string",
                            "value": "value2"
                        },
                        {
                            "key": "otel.library.name",
                            "type": "string",
                            "value": "io.opentelemetry.spring-webmvc-3.1"
                        },
                        {
                            "key": "otel.library.version",
                            "type": "string",
                            "value": "1.14.0-alpha-SNAPSHOT"
                        },
                        {
                            "key": "otel.scope.version",
                            "type": "string",
                            "value": "1.14.0-alpha-SNAPSHOT"
                        },
                        {
                            "key": "thread.id",
                            "type": "string",
                            "value": "43"
                        },
                        {
                            "key": "thread.name",
                            "type": "string",
                            "value": "http-nio-8080-exec-3"
                        },
                        {
                            "key": "clusterID",
                            "type": "string",
                            "value": "dev"
                        },
                        {
                            "key": "ns",
                            "type": "string",
                            "value": "tuhao-1"
                        },
                        {
                            "key": "otel.scope.name",
                            "type": "string",
                            "value": "io.opentelemetry.spring-webmvc-3.1"
                        },
                        {
                            "key": "internal.span.format",
                            "type": "string",
                            "value": "zipkin"
                        }
                    ],
                    "logs": [],
                    "processID": "p2",
                    "warnings": null
                },
                {
                    "traceID": "96be510babcc56f2a97085cc379a9f83",
                    "spanID": "d5feb1703407485d",
                    "operationName": "/hello",
                    "references": [
                        {
                            "refType": "CHILD_OF",
                            "traceID": "96be510babcc56f2a97085cc379a9f83",
                            "spanID": "617069213aadca5e"
                        }
                    ],
                    "startTime": 1654001468989000,
                    "duration": 4759,
                    "tags": [
                        {
                            "key": "net.peer.ip",
                            "type": "string",
                            "value": "127.0.0.1"
                        },
                        {
                            "key": "otel.library.name",
                            "type": "string",
                            "value": "io.opentelemetry.tomcat-7.0"
                        },
                        {
                            "key": "otel.scope.name",
                            "type": "string",
                            "value": "io.opentelemetry.tomcat-7.0"
                        },
                        {
                            "key": "thread.name",
                            "type": "string",
                            "value": "http-nio-8080-exec-3"
                        },
                        {
                            "key": "key2",
                            "type": "string",
                            "value": "value2"
                        },
                        {
                            "key": "http.status_code",
                            "type": "string",
                            "value": "200"
                        },
                        {
                            "key": "http.target",
                            "type": "string",
                            "value": "/hello"
                        },
                        {
                            "key": "net.transport",
                            "type": "string",
                            "value": "ip_tcp"
                        },
                        {
                            "key": "thread.id",
                            "type": "string",
                            "value": "43"
                        },
                        {
                            "key": "http.route",
                            "type": "string",
                            "value": "/hello"
                        },
                        {
                            "key": "http.flavor",
                            "type": "string",
                            "value": "1.1"
                        },
                        {
                            "key": "http.host",
                            "type": "string",
                            "value": "localhost:8080"
                        },
                        {
                            "key": "http.response_content_length",
                            "type": "string",
                            "value": "23"
                        },
                        {
                            "key": "net.peer.port",
                            "type": "string",
                            "value": "55438"
                        },
                        {
                            "key": "clusterID",
                            "type": "string",
                            "value": "dev"
                        },
                        {
                            "key": "http.scheme",
                            "type": "string",
                            "value": "http"
                        },
                        {
                            "key": "http.user_agent",
                            "type": "string",
                            "value": "Java/11.0.14.1"
                        },
                        {
                            "key": "ns",
                            "type": "string",
                            "value": "tuhao-1"
                        },
                        {
                            "key": "otel.library.version",
                            "type": "string",
                            "value": "1.14.0-alpha-SNAPSHOT"
                        },
                        {
                            "key": "otel.scope.version",
                            "type": "string",
                            "value": "1.14.0-alpha-SNAPSHOT"
                        },
                        {
                            "key": "http.method",
                            "type": "string",
                            "value": "GET"
                        },
                        {
                            "key": "span.kind",
                            "type": "string",
                            "value": "server"
                        },
                        {
                            "key": "internal.span.format",
                            "type": "string",
                            "value": "zipkin"
                        }
                    ],
                    "logs": [],
                    "processID": "p2",
                    "warnings": null
                }
            ],
            "processes": {
                "p1": {
                    "serviceName": "otel-client",
                    "tags": [
                        {
                            "key": "ip",
                            "type": "string",
                            "value": "10.80.0.14"
                        }
                    ]
                },
                "p2": {
                    "serviceName": "otel-server",
                    "tags": [
                        {
                            "key": "ip",
                            "type": "string",
                            "value": "10.80.0.14"
                        }
                    ]
                }
            },
            "warnings": null
        }
    ],
    "total": 0,
    "limit": 0,
    "offset": 0,
    "errors": null
}

[laurit]

Probably because HttpURLConnection instrumentation ends the span on call to getInputStream where just the response status is available. The server span is ended when the whole response has been written.

[tuhao1020]

Is there a way to optimize this problem?

[tuhao1020]

@laurit In this screenshot parent span ends later than child span. According to your explanation, parent spans should always end before child spans.

[laurit]

I don't think it would mean that child span has to always end before parent. For example server could buffer small responses and really send the response at a point where the child span has already been completed. I'm not claiming that this is definitely what happens here.