Hi Daniel,
Thanks for the quick response!
> > While analysing traffic generated by "virsh vol-download", I noticed
> > that the download stream exhibits the following pattern (over
> > qemu+ssh://):
> >
> > <Start>
> > Read 4 bytes (= frame length field)
> > Read 262144 bytes (= header + payload ; VIR_NET_MESSAGE_HEADER_MAX
> > (24) + VIR_NET_MESSAGE_LEGACY_PAYLOAD_MAX (262120))
> > Read 4 bytes (= frame length field)
> > Read 48 bytes (= header + payload)
> > <Go back to Start>
> >
> > While nothing seems to be actually wrong with this pattern, the
I meant to say: while nothing seems to be wrong *with the data* being
transferred in this pattern...
> > average payload on large data transfers is only (262120+24)/2 ==
> > 131072 and the CPU makes double the iterations necessary. I'll be
> > trying to figure out where this comes from, but I imagine that will be
> > pretty hard to track down.
> >
> > Two questions:
> > 1. Do you see the same thing?
> > 2. Any ideas/hints where I could start looking?
>
> I'd suggest enabling RPC tracing with systemtap, or debug logs, to see
> what the messages being sent are.
>
> The 262144 byte message will be VIR_NET_STREAM with data payload.
>
> The 48 byte message is slightly surprising, but given you're using
> vol-download, I'm going to guess that the volume is sparse, and
I didn't specify the --sparse flag; not sure if there's anything
turning it regardless, but I wouldn't expect any holes to be in the
transfer.
> say this the 48 byte message is a VIR_NET_STREAM_HOLE message
> skipping over the transfer of a large area of zeros.
Using Protocol::Sys::Virt, I wrote a protocol analyzer and using the
"ext" transfer mechanism I'm able to capture the transfer streams. I'm
seeing the pattern over qemu+ssh:// to a remote server, but I see the
same pattern in the stream I recorded using the qemu+ext:///. This is
what shows up:
4: 262144:
["header",{"proc":209,"prog":536903814,"serial":10,"status":2,"type":3,"vers":1},"final",false,"data","<data
length: 262120>","hole",null]
4: 48:
["header",{"proc":209,"prog":536903814,"serial":10,"status":2,"type":3,"vers":1},"final",false,"data","<data
length: 24>","hole",null]
The "4: 48: " means 2 reads, one of 4 bytes and one of 48 bytes. The
second read is a header with the fields given above and a data section
of 24 bytes. The important part is the "type" field where the value 3
is VIR_NET_STREAM, just as the message right above it. From this, I
conclude that both transfer data and neither transfers a hole. I was
thinking that the first data frame might be 24 bytes short, causing
the 24-byte-out-of-sync of all future frames, but that's not the case:
the initial stream data frame is 262144; here's the rpc response and
the first two stream frames:
4: 24:
["header",{"proc":209,"prog":536903814,"serial":10,"status":0,"type":1,"vers":1},"data",null,"error",null]
4: 262144:
["header",{"proc":209,"prog":536903814,"serial":10,"status":2,"type":3,"vers":1},"final",false,"data","<data
length: 262120>","hole",null]
4: 48:
["header",{"proc":209,"prog":536903814,"serial":10,"status":2,"type":3,"vers":1},"final",false,"data","<data
length: 24>","hole",null]
If you want, I can share the tools and the protocol-decoded data
stream (the gzipped decoded data stream is only ~10kB)?
By the way, the "capture" tool I'm using is a simple script:
#!/usr/bin/bash
tee -p ./recording-upstream | nc -q0 -U /run/libvirt/libvirt-sock |
tee -p ./recording-downstream
I'll add the protocol decoder to the Protocol::Sys::Virt distribution
in the examples directory and upload to CPAN.
--
Bye,
Erik.
http://efficito.com -- Hosted accounting and ERP.
Robust and Flexible. No vendor lock-in.
