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.