gvfsd-dav is extremely slow and eating 100% CPU with HTTP/2
Versions:
- Arch Linux, GNOME 45
- gvfs 1.52.1-1
- libsoup3 3.4.3-1
- libnghttp2 1.57.0-1
When opening a large file (larger than 500M) like video, gvfsd-dav eats a CPU core and applications using the file hangs. This is not the case with HTTP/1.1.
Server code (This bug also exists with Nextcloud webdav, but this golang code is much easier to test, I guess):
package main
import (
"crypto/rand"
"crypto/rsa"
"crypto/tls"
"crypto/x509"
"crypto/x509/pkix"
"log"
"math/big"
"net"
"net/http"
"time"
"golang.org/x/net/webdav"
)
// ref: https://go.dev/src/crypto/tls/generate_cert.go
func GenSelfSignedTLSCertificate() (tls.Certificate, error) {
priv, err := rsa.GenerateKey(rand.Reader, 2048)
if err != nil {
return tls.Certificate{}, err
}
template := x509.Certificate{
SerialNumber: big.NewInt(1),
Subject: pkix.Name{
Country: []string{"GVFSD TESTING"},
Organization: []string{"GVFSD-DAV TESTING"},
},
NotBefore: time.Now(),
NotAfter: time.Now().AddDate(10, 0, 0),
KeyUsage: x509.KeyUsageDigitalSignature | x509.KeyUsageCertSign,
ExtKeyUsage: []x509.ExtKeyUsage{x509.ExtKeyUsageServerAuth},
BasicConstraintsValid: true,
IPAddresses: []net.IP{net.ParseIP("127.0.0.1")},
DNSNames: []string{"localhost"},
IsCA: true,
}
certBytes, err := x509.CreateCertificate(rand.Reader, &template, &template, &priv.PublicKey, priv)
if err != nil {
return tls.Certificate{}, err
}
return tls.Certificate{Certificate: [][]byte{certBytes}, PrivateKey: priv}, nil
}
func main() {
cert, err := GenSelfSignedTLSCertificate()
if err != nil {
panic(err)
}
// Initialize the WebDAV filesystem
fs := &webdav.Handler{
Prefix: "/webdav",
FileSystem: webdav.Dir("/home/username/Videos/"), // replace with your directory to be shared
LockSystem: webdav.NewMemLS(),
}
http.HandleFunc("/", fs.ServeHTTP)
server := http.Server{
Addr: "127.0.0.1:1443",
Handler: http.DefaultServeMux,
TLSConfig: &tls.Config{Certificates: []tls.Certificate{cert}, NextProtos: []string{"h2"}}, // h2 for HTTP/2 only
// TLSConfig: &tls.Config{Certificates: []tls.Certificate{cert}, NextProtos: []string{"http/1.1"}}, // http/1.1 for HTTP/1.1 only
}
log.Fatal(server.ListenAndServeTLS("", ""))
}
And connect with davs://localhost:1443/webdav
.
The server only takes ~2% CPU when gvfsd-dav eats 100%, so the golang server is not the bottleneck. When changing TLSConfig
from h2 to http/1.1, gvfsd-dav works smoothly.
Backtrace:
#0 0x00007fec406cb3a7 in g_slist_last (list=0x564689937750 = {...}, list@entry=0x564684efa2a0 = {...}) at ../glib/glib/gslist.c:834
#1 0x00007fec406ccd75 in g_slist_append (list=0x564684efa2a0 = {...}, data=0x5646a035d170) at ../glib/glib/gslist.c:247
new_list = 0x5646a035d1a0 = {0x5646a035d170}
last = <optimized out>
#2 0x00007fec405ec928 in soup_body_input_stream_http2_add_data
(size=16375, data=0x7ffe87227249 "\240\340\270c\267o\216u\027\031\234\362\352z\215Y\247і\356\363[ \346\302\327\337{\035\\SA\372\\>\233٪\373\251j\017\307\346Se\216\251\244\331\024\240\222\026\355\365U^*y6\277\032\221\003\271&\311\334Z\f\373\362\n~\373Ma\031\223R7%\266\342F\314{\251\241s\243J\354\201\005v", stream=<optimized out>) at ../libsoup/libsoup/http2/soup-body-input-stream-http2.c:92
priv = 0x564684f0cd40
io = 0x564685528e60
msgdata = 0x564685500c60
__func__ = "on_data_chunk_recv_callback"
#3 soup_body_input_stream_http2_add_data
(size=16375, data=0x7ffe87227249 "\240\340\270c\267o\216u\027\031\234\362\352z\215Y\247і\356\363[ \346\302\327\337{\035\\SA\372\\>\233٪\373\251j\017\307\346Se\216\251\244\331\024\240\222\026\355\365U^*y6\277\032\221\003\271&\311\334Z\f\373\362\n~\373Ma\031\223R7%\266\342F\314{\251\241s\243J\354\201\005v", stream=<optimized out>) at ../libsoup/libsoup/http2/soup-body-input-stream-http2.c:81
io = 0x564685528e60
msgdata = 0x564685500c60
__func__ = "on_data_chunk_recv_callback"
#4 on_data_chunk_recv_callback
(session=<optimized out>, flags=<optimized out>, stream_id=125, data=0x7ffe87227249 "\240\340\270c\267o\216u\027\031\234\362\352z\215Y\247і\356\363[ \346\302\327\337{\035\\SA\372\\>\233٪\373\251j\017\307\346Se\216\251\244\331\024\240\222\026\355\365U^*y6\277\032\221\003\271&\311\334Z\f\373\362\n~\373Ma\031\223R7%\266\342F\314{\251\241s\243J\354\201\005v", len=16375, user_data=0x564685528e60)
at ../libsoup/libsoup/http2/soup-client-message-io-http2.c:835
io = 0x564685528e60
msgdata = 0x564685500c60
__func__ = "on_data_chunk_recv_callback"
#5 0x00007fec3fe499c9 in nghttp2_session_mem_recv () at /usr/lib/libnghttp2.so.14
#6 0x00007fec405ed9f1 in io_read
(io=io@entry=0x564685528e60, blocking=blocking@entry=0, cancellable=cancellable@entry=0x0, error=error@entry=0x7ffe8722b280)
at ../libsoup/libsoup/http2/soup-client-message-io-http2.c:450
buffer = "\000@\000\000\000\000\000\000}\240\340\270c\267o\216u\027\031\234\362\352z\215Y\247і\356\363[ \346\302\327\337{\035\\SA\372\\>\233٪\373\251j\017\307\346Se\216\251\244\331\024\240\222\026\355\365U^*y6\277\032\221\003\271&\311\334Z\f\373\362\n~\373Ma\031\223R7%\266\342F\314{\251\241s\243J\354\201\005v\000\206\000A\016\340\3214\006\000\004pP@\000\000\000\0009jv\323u<\266\353\227\rY\204k\224\351{Kùw\001Y\343\370\003\305r\001u\232\307ࣸ\315\352\307r\252\314\314s\307ֱF\200L<\016L\374c5\357\030\260\000\000\000\b\257o\216\374\\\355\353\372q\314\320\000\3450\215q\250G\242\034"...
read = 16384
ret = <optimized out>
__func__ = "io_read"
#7 0x00007fec405edb7f in io_read_ready (stream=<optimized out>, io=0x564685528e60) at ../libsoup/libsoup/http2/soup-client-message-io-http2.c:476
error = 0x0
progress = <optimized out>
conn = 0x564684e589f0
#8 0x00007fec406aaf19 in g_main_dispatch (context=0x564684e34530) at ../glib/glib/gmain.c:3476
dispatch = 0x7fec40888eb0 <pollable_source_dispatch>
prev_source = 0x0
begin_time_nsec = 480123959964064
--Type <RET> for more, q to quit, c to continue without paging--c
was_in_call = 0
user_data = 0x564685528e60
callback = 0x7fec405edae0 <io_read_ready>
cb_funcs = 0x7fec4079b380 <g_source_callback_funcs>
cb_data = 0x564685547770
need_destroy = <optimized out>
source = 0x564684ef6e40
current = 0x564684e3a5a0
i = 3
__func__ = "g_main_dispatch"
#9 0x00007fec407092b7 in g_main_context_dispatch_unlocked (context=0x564684e34530) at ../glib/glib/gmain.c:4284
max_priority = 2147483647
timeout = -1
some_ready = 1
nfds = 2
allocated_nfds = 11
fds = 0x564685500390
begin_time_nsec = 480123959414238
#10 g_main_context_iterate_unlocked.isra.0 (context=0x564684e34530, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
at ../glib/glib/gmain.c:4349
max_priority = 2147483647
timeout = -1
some_ready = 1
nfds = 2
allocated_nfds = 11
fds = 0x564685500390
begin_time_nsec = 480123959414238
#11 0x00007fec406abb47 in g_main_loop_run (loop=0x564684e3a4a0) at ../glib/glib/gmain.c:4551
__func__ = "g_main_loop_run"
#12 0x00005646846704ef in daemon_main
(argc=argc@entry=4, argv=argv@entry=0x7ffe8722b698, max_job_threads=max_job_threads@entry=1, default_type=default_type@entry=0x56468467633a "dav", mountable_name=mountable_name@entry=0x0, first_type_name=first_type_name@entry=0x56468467633a "dav") at ../gvfs/daemon/daemon-main.c:398
var_args = {{gp_offset = 48, fp_offset = 48, overflow_arg_area = 0x7ffe8722b570, reg_save_area = 0x7ffe8722b450}}
type = 0x0
name_owner_id = 1
data = 0x564684e2e270
#13 0x000056468466908a in main (argc=4, argv=0x7ffe8722b698) at ../gvfs/daemon/daemon-main-generic.c:45
Seems to be the fault of libsoup (?) but I don't know how to report to libsoup for this bug. Move this issue if necessary.
Edited by Keyu Tao