Progress not showing up before the last second #444

guyzmo · 2016-05-26T09:09:16Z

I've implemented the Progress class to implement a nice progress bar:

https://github.com/guyzmo/git-repo/blob/master/git_repo/services/service.py#L46-56

I'm then using it, for example here:

https://github.com/guyzmo/git-repo/blob/master/git_repo/services/service.py#L196-202

And then, when I clone a very large repository (like mozilla's gecko):

% git hub clone mozilla/gecko-dev
Pulling from github |████████████████████████████████|
Successfully cloned `https://github.com/guyzmo/git-repo` into `./git-repo`!

the progress bar is "progressing" (i.e. incrementing from 0 to 100%), but it shows up only at the very end of the fetching, after hanging for a long while. I started to debug it, and it looks like it's related to subprocess stuff.

Though, I might be implementing it wrong, which is why I'm asking here while I'm still debugging that issue.

The text was updated successfully, but these errors were encountered:

Byron · 2016-05-26T12:56:34Z

As far as I know, the progress line parsing is immediate, and thus will produce results in real time, similar to what you see on the command-line.
To understand what's the problem in your case, I recommend having a look at the parsing code to understand how exactly it works.
As an alternative step that you seem to have taken already, I would believe that just printing the remote progress arguments will indicate they are indeed provided in real-time.
If that's the case indeed, the problem would lie with the way the progress bar is used.

However, I am interested in your findings, maybe there is something unexpected here.

guyzmo · 2016-05-26T16:04:28Z

There's definitely something fishy going on, I have replaced my "progress bar" instance with the following code:

and then I ran the command. I made an asciicinema output of the command to better see the pausing, followed by the output:

https://asciinema.org/a/cwoo3r1gnziyxgycbybd1p485

which is not outputting at the same rate as a raw git clone command:

http:https://asciinema.org/a/0u002zielzbpprrj6e5h20hpa

I already looked at the parsing code, and I agree it's looking totally fine, and it should work as intended. So maybe, a good idea would be to try to replicate the issue through a minimal snippet, to see whether my code could be interfering (which I believe should not, but who knows?).

I'll also try to add printouts in the parser to see where it's blocking.

guyzmo · 2016-05-26T16:44:58Z

Ok, I've added a bunch of printouts, along with a timer to find where the pausing is happening (cf below).

So it's pretty obvious that the pausing is happening in _get_fetch_info_from_stderr() between marks 2 and 3, which is:

         print_time('Remote._get_fetch_info_from_stderr', 2)
         for line in proc.stderr.readlines():
             print_time('Remote._get_fetch_info_from_stderr', 3)

and now, it's pretty clear what's happening, on a file object readlines() is reading all output up until EOF and returns it as a list, it does not return an iterator. So as a fix, I'll try next with:

         print_time('Remote._get_fetch_info_from_stderr', 2)
         for line in proc.stderr:
             print_time('Remote._get_fetch_info_from_stderr', 3)

which is the right way to iterate line by line over a file object.

full log:

Cloning GitPython…
     1.489 | RemoteProgress.__init__()
setup
     1.490 | Remote.pull(master, <git_repo.services.service.ProgressBar object at 0x7f6d7e2d5630>, {}
     1.515 | Remote._get_fetch_info_from_stderr(github, <git.cmd.Git.AutoInterrupt object at 0x7f6d7e2c4780>, <git_repo.services.service.ProgressBar object at 0x7f6d7e2d5630>)
     1.516 | Remote._get_fetch_info_from_stderr 1
     1.516 | new_message_handler()
     1.516 | Remote._get_fetch_info_from_stderr 2
     5.497 | Remote._get_fetch_info_from_stderr 3
     5.497 | Remote._get_fetch_info_from_stderr 4
     5.497 | RemoteProgress.new_message_handler()::handler(remote: Counting objects: 10330, done.)
     5.497 | RemoteProgress._parse_progress_line remote: Counting objects: 10330, done.
     5.498 | update 7, 10330.0, ,
     5.498 | Remote._get_fetch_info_from_stderr 5
     5.498 | Remote._get_fetch_info_from_stderr 3
     5.498 | Remote._get_fetch_info_from_stderr 4
remote: Compressing objects: 100% (95/95), done.        er(remote: Compressing objects:   1% (1/95))
remote: Compressing objects: 100% (95/95), done.    ote: Compressing objects:   1% (1/95)
     5.498 | update 9, 1.0, 95.0,
     5.498 | update 8, 2.0, 95.0,
     5.498 | update 8, 3.0, 95.0,
     5.498 | update 8, 4.0, 95.0,
     5.498 | update 8, 5.0, 95.0,
     5.498 | update 8, 6.0, 95.0,
     5.498 | update 8, 7.0, 95.0,
     5.498 | update 8, 8.0, 95.0,
     5.498 | update 8, 9.0, 95.0,
     5.498 | update 8, 10.0, 95.0,
     5.498 | update 8, 11.0, 95.0,
     5.498 | update 8, 12.0, 95.0,
     5.498 | update 8, 13.0, 95.0,
     5.498 | update 8, 14.0, 95.0,
     5.498 | update 8, 15.0, 95.0,
     5.498 | update 8, 16.0, 95.0,
     5.498 | update 8, 17.0, 95.0,
     5.498 | update 8, 18.0, 95.0,
     5.498 | update 8, 19.0, 95.0,
     5.499 | update 8, 20.0, 95.0,
     5.499 | update 8, 21.0, 95.0,
     5.499 | update 8, 22.0, 95.0,
     5.499 | update 8, 23.0, 95.0,
     5.499 | update 8, 24.0, 95.0,
     5.499 | update 8, 25.0, 95.0,
     5.499 | update 8, 26.0, 95.0,
     5.499 | update 8, 27.0, 95.0,
     5.499 | update 8, 28.0, 95.0,
     5.499 | update 8, 29.0, 95.0,
     5.499 | update 8, 30.0, 95.0,
     5.499 | update 8, 31.0, 95.0,
     5.499 | update 8, 32.0, 95.0,
     5.499 | update 8, 33.0, 95.0,
     5.499 | update 8, 34.0, 95.0,
     5.499 | update 8, 35.0, 95.0,
     5.499 | update 8, 36.0, 95.0,
     5.499 | update 8, 37.0, 95.0,
     5.499 | update 8, 38.0, 95.0,
     5.499 | update 8, 39.0, 95.0,
     5.499 | update 8, 40.0, 95.0,
     5.499 | update 8, 41.0, 95.0,
     5.499 | update 8, 42.0, 95.0,
     5.499 | update 8, 43.0, 95.0,
     5.499 | update 8, 44.0, 95.0,
     5.499 | update 8, 45.0, 95.0,
     5.499 | update 8, 46.0, 95.0,
     5.499 | update 8, 47.0, 95.0,
     5.500 | update 8, 48.0, 95.0,
     5.500 | update 8, 49.0, 95.0,
     5.500 | update 8, 50.0, 95.0,
     5.500 | update 8, 51.0, 95.0,
     5.500 | update 8, 52.0, 95.0,
     5.500 | update 8, 53.0, 95.0,
     5.500 | update 8, 54.0, 95.0,
     5.500 | update 8, 55.0, 95.0,
     5.500 | update 8, 56.0, 95.0,
     5.500 | update 8, 57.0, 95.0,
     5.500 | update 8, 58.0, 95.0,
     5.500 | update 8, 59.0, 95.0,
     5.500 | update 8, 60.0, 95.0,
     5.500 | update 8, 61.0, 95.0,
     5.500 | update 8, 62.0, 95.0,
     5.500 | update 8, 63.0, 95.0,
     5.500 | update 8, 64.0, 95.0,
     5.500 | update 8, 65.0, 95.0,
     5.500 | update 8, 66.0, 95.0,
     5.500 | update 8, 67.0, 95.0,
     5.500 | update 8, 68.0, 95.0,
     5.500 | update 8, 69.0, 95.0,
     5.500 | update 8, 70.0, 95.0,
     5.500 | update 8, 71.0, 95.0,
     5.500 | update 8, 72.0, 95.0,
     5.500 | update 8, 73.0, 95.0,
     5.500 | update 8, 74.0, 95.0,
     5.500 | update 8, 75.0, 95.0,
     5.501 | update 8, 76.0, 95.0,
     5.501 | update 8, 77.0, 95.0,
     5.501 | update 8, 78.0, 95.0,
     5.501 | update 8, 79.0, 95.0,
     5.501 | update 8, 80.0, 95.0,
     5.501 | update 8, 81.0, 95.0,
     5.501 | update 8, 82.0, 95.0,
     5.501 | update 8, 83.0, 95.0,
     5.501 | update 8, 84.0, 95.0,
     5.501 | update 8, 85.0, 95.0,
     5.501 | update 8, 86.0, 95.0,
     5.501 | update 8, 87.0, 95.0,
     5.501 | update 8, 88.0, 95.0,
     5.501 | update 8, 89.0, 95.0,
     5.501 | update 8, 90.0, 95.0,
     5.501 | update 8, 91.0, 95.0,
     5.501 | update 8, 92.0, 95.0,
     5.501 | update 8, 93.0, 95.0,
     5.501 | update 8, 94.0, 95.0,
     5.501 | update 8, 95.0, 95.0,
     5.501 | update 10, 95.0, 95.0,
     5.501 | Remote._get_fetch_info_from_stderr 5
     5.501 | Remote._get_fetch_info_from_stderr 3
     5.501 | Remote._get_fetch_info_from_stderr 4
remote: Total 10330 (delta 65), reused 9 (delta 9), pack-reused 10224           0% (1/10330))
remote: Total 10330 (delta 65), reused 9 (delta 9), pack-reused 10224 0% (1/10330)
     5.501 | update 33, 1.0, 10330.0,
     5.502 | update 32, 104.0, 10330.0,
     5.502 | update 32, 207.0, 10330.0,
     5.502 | update 32, 310.0, 10330.0,
     5.502 | update 32, 414.0, 10330.0,
     5.502 | update 32, 517.0, 10330.0,
     5.502 | update 32, 620.0, 10330.0,
     5.502 | update 32, 724.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 827.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 930.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 1033.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 1137.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 1240.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 1343.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 1447.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 1550.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 1653.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 1757.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 1860.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 1963.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 2066.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 2170.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 2273.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 2376.0, 10330.0, , 340.00 KiB | 671.00 KiB/s
     5.502 | update 32, 2449.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.502 | update 32, 2480.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.502 | update 32, 2583.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 2686.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 2790.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 2893.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 2996.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 3099.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 3203.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 3306.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 3409.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 3513.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 3616.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 3719.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 3823.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 3926.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 4029.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 4132.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 4236.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 4339.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 4442.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 4546.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 4649.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 4752.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 4856.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 4959.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 5062.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 5165.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.503 | update 32, 5269.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 5372.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 5475.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 5579.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 5682.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 5785.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 5889.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 5992.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 6095.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 6198.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 6302.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 6405.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 6508.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 6612.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 6715.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 6818.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 6922.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 7025.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 7128.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 7231.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 7335.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 7438.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 7541.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 7645.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 7748.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.504 | update 32, 7851.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 7955.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 8058.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 8161.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 8264.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 8368.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 8471.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 8574.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 8678.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 8781.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 8884.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 8988.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 9091.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 9194.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 9297.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 9401.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 9504.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 9607.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 9711.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 9814.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 9917.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 10021.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | update 32, 10124.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.505 | RemoteProgress.line_dropped
     5.505 | Remote._get_fetch_info_from_stderr 5
     5.505 | Remote._get_fetch_info_from_stderr 3
     5.505 | Remote._get_fetch_info_from_stderr 4
Receiving objects: 100% (10330/10330), 5.93 MiB | 1.57 MiB/s, done.g objects:  99% (10227/10330), 1.57 MiB | 1.57 MiB/s)
Receiving objects: 100% (10330/10330), 5.93 MiB | 1.57 MiB/s, done.  99% (10227/10330), 1.57 MiB | 1.57 MiB/s
     5.506 | update 32, 10227.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.506 | update 32, 10330.0, 10330.0, , 1.57 MiB | 1.57 MiB/s
     5.506 | update 34, 10330.0, 10330.0, , 5.93 MiB | 1.57 MiB/s
     5.506 | Remote._get_fetch_info_from_stderr 5
     5.506 | Remote._get_fetch_info_from_stderr 3
     5.506 | Remote._get_fetch_info_from_stderr 4
Resolving deltas: 100% (5911/5911), done.andler()::handler(Resolving deltas:   0% (0/5911))
Resolving deltas: 100% (5911/5911), done.ss_line Resolving deltas:   0% (0/5911)
     5.506 | update 65, 0.0, 5911.0,
     5.506 | update 64, 62.0, 5911.0,
     5.506 | update 64, 130.0, 5911.0,
     5.506 | update 64, 184.0, 5911.0,
     5.506 | update 64, 237.0, 5911.0,
     5.506 | update 64, 305.0, 5911.0,
     5.506 | update 64, 359.0, 5911.0,
     5.506 | update 64, 419.0, 5911.0,
     5.506 | update 64, 477.0, 5911.0,
     5.506 | update 64, 539.0, 5911.0,
     5.506 | update 64, 592.0, 5911.0,
     5.506 | update 64, 664.0, 5911.0,
     5.506 | update 64, 725.0, 5911.0,
     5.506 | update 64, 772.0, 5911.0,
     5.506 | update 64, 828.0, 5911.0,
     5.507 | update 64, 921.0, 5911.0,
     5.507 | update 64, 969.0, 5911.0,
     5.507 | update 64, 1010.0, 5911.0,
     5.507 | update 64, 1068.0, 5911.0,
     5.507 | update 64, 1124.0, 5911.0,
     5.507 | update 64, 1183.0, 5911.0,
     5.507 | update 64, 1242.0, 5911.0,
     5.507 | update 64, 1312.0, 5911.0,
     5.507 | update 64, 1360.0, 5911.0,
     5.507 | update 64, 1419.0, 5911.0,
     5.507 | update 64, 1483.0, 5911.0,
     5.507 | update 64, 1537.0, 5911.0,
     5.507 | update 64, 1596.0, 5911.0,
     5.507 | update 64, 1657.0, 5911.0,
     5.507 | update 64, 1715.0, 5911.0,
     5.507 | update 64, 1778.0, 5911.0,
     5.507 | update 64, 1833.0, 5911.0,
     5.507 | update 64, 1893.0, 5911.0,
     5.507 | update 64, 1951.0, 5911.0,
     5.507 | update 64, 2018.0, 5911.0,
     5.507 | update 64, 2069.0, 5911.0,
     5.507 | update 64, 2128.0, 5911.0,
     5.507 | update 64, 2191.0, 5911.0,
     5.507 | update 64, 2254.0, 5911.0,
     5.508 | update 64, 2329.0, 5911.0,
     5.508 | update 64, 2371.0, 5911.0,
     5.508 | update 64, 2427.0, 5911.0,
     5.508 | update 64, 2505.0, 5911.0,
     5.508 | update 64, 2555.0, 5911.0,
     5.508 | update 64, 2604.0, 5911.0,
     5.508 | update 64, 2698.0, 5911.0,
     5.508 | update 64, 2768.0, 5911.0,
     5.508 | update 64, 2814.0, 5911.0,
     5.508 | update 64, 2840.0, 5911.0,
     5.508 | update 64, 2939.0, 5911.0,
     5.508 | update 64, 2957.0, 5911.0,
     5.508 | update 64, 3027.0, 5911.0,
     5.508 | update 64, 3083.0, 5911.0,
     5.508 | update 64, 3138.0, 5911.0,
     5.508 | update 64, 3221.0, 5911.0,
     5.508 | update 64, 3256.0, 5911.0,
     5.508 | update 64, 3328.0, 5911.0,
     5.508 | update 64, 3376.0, 5911.0,
     5.508 | update 64, 3436.0, 5911.0,
     5.508 | update 64, 3505.0, 5911.0,
     5.508 | update 64, 3637.0, 5911.0,
     5.508 | update 64, 3688.0, 5911.0,
     5.509 | update 64, 3740.0, 5911.0,
     5.509 | update 64, 3786.0, 5911.0,
     5.509 | update 64, 3887.0, 5911.0,
     5.509 | update 64, 3935.0, 5911.0,
     5.509 | update 64, 3961.0, 5911.0,
     5.509 | update 64, 4030.0, 5911.0,
     5.509 | update 64, 4095.0, 5911.0,
     5.509 | update 64, 4139.0, 5911.0,
     5.509 | update 64, 4200.0, 5911.0,
     5.509 | update 64, 4261.0, 5911.0,
     5.509 | update 64, 4317.0, 5911.0,
     5.509 | update 64, 4375.0, 5911.0,
     5.509 | update 64, 4443.0, 5911.0,
     5.509 | update 64, 4513.0, 5911.0,
     5.509 | update 64, 4560.0, 5911.0,
     5.509 | update 64, 4627.0, 5911.0,
     5.509 | update 64, 4744.0, 5911.0,
     5.509 | update 64, 4803.0, 5911.0,
     5.509 | update 64, 4848.0, 5911.0,
     5.509 | update 64, 4908.0, 5911.0,
     5.509 | update 64, 4966.0, 5911.0,
     5.509 | update 64, 5032.0, 5911.0,
     5.509 | update 64, 5086.0, 5911.0,
     5.510 | update 64, 5143.0, 5911.0,
     5.510 | update 64, 5202.0, 5911.0,
     5.510 | update 64, 5268.0, 5911.0,
     5.510 | update 64, 5327.0, 5911.0,
     5.510 | update 64, 5381.0, 5911.0,
     5.510 | update 64, 5462.0, 5911.0,
     5.510 | update 64, 5501.0, 5911.0,
     5.510 | update 64, 5559.0, 5911.0,
     5.510 | update 64, 5626.0, 5911.0,
     5.510 | update 64, 5675.0, 5911.0,
     5.510 | update 64, 5755.0, 5911.0,
     5.510 | update 64, 5795.0, 5911.0,
     5.510 | update 64, 5863.0, 5911.0,
     5.510 | update 64, 5911.0, 5911.0,
     5.510 | update 66, 5911.0, 5911.0,
     5.510 | Remote._get_fetch_info_from_stderr 5
     5.510 | Remote._get_fetch_info_from_stderr 3
     5.510 | Remote._get_fetch_info_from_stderr 4
     5.510 | RemoteProgress.new_message_handler()::handler(From github.com:gitpython-developers/GitPython)
     5.510 | RemoteProgress._parse_progress_line From github.com:gitpython-developers/GitPython
     5.510 | RemoteProgress.line_dropped
     5.510 | Remote._get_fetch_info_from_stderr 5
     5.510 | Remote._get_fetch_info_from_stderr 3
     5.510 | Remote._get_fetch_info_from_stderr 4
     5.510 | RemoteProgress.new_message_handler()::handler( * branch            master     -> FETCH_HEAD)
     5.510 | RemoteProgress._parse_progress_line  * branch            master     -> FETCH_HEAD
     5.511 | RemoteProgress.line_dropped
     5.511 | Remote._get_fetch_info_from_stderr 5
     5.511 | Remote._get_fetch_info_from_stderr 3
     5.511 | Remote._get_fetch_info_from_stderr 4
     5.511 | RemoteProgress.new_message_handler()::handler( * [new branch]      master     -> github/master)
     5.511 | RemoteProgress._parse_progress_line  * [new branch]      master     -> github/master
     5.511 | RemoteProgress.line_dropped
     5.511 | Remote._get_fetch_info_from_stderr 5
     5.511 | Remote._get_fetch_info_from_stderr 6
Fetch head lines do not match lines provided via progress information
length of progress lines 2 should be equal to lines in FETCH_HEAD file 1
Will ignore extra progress lines or fetch head lines.

Successfully cloned `https://github.com/gitpython-developers/GitPython` into `./GitPython`!

Byron · 2016-05-26T16:55:29Z

Great debugging and findings ! I just pushed the fix !

And thanks a lot !

guyzmo · 2016-05-26T17:08:52Z

Well, it's actually still not very smooth:

https://asciinema.org/a/55m8ugnq1j43k69keiasnjzoo

and, as I am using master's HEAD, there's an issue with it showing:

Fetch head lines do not match lines provided via progress information                                     length of progress lines 2 should be equal to lines in FETCH_HEAD file 1                                                                                         Will ignore extra progress lines or fetch head lines.

I guess it's not relevant to the issue at hand, though.

Then, I ran it again with the fix and timers in place, and here's the output:

Cloning GitPython…
     2.486 | RemoteProgress.__init__()
setup
     2.486 | Remote.pull(master, <git_repo.services.service.ProgressBar object at 0x7fa89dc66168>, {}
     2.500 | Remote._get_fetch_info_from_stderr(github, <git.cmd.Git.AutoInterrupt object at 0x7fa89dc28748>, <git_repo.services.service.ProgressBar object at 0x
7fa89dc66168>)
     2.500 | Remote._get_fetch_info_from_stderr 1
     2.500 | new_message_handler()
     2.500 | Remote._get_fetch_info_from_stderr 2
     4.319 | Remote._get_fetch_info_from_stderr 3
     4.319 | Remote._get_fetch_info_from_stderr 4
     4.319 | RemoteProgress.new_message_handler()::handler(remote: Counting objects: 10334, done.
)
     4.319 | RemoteProgress._parse_progress_line remote: Counting objects: 10334, done.
     4.319 | update 7, 10334.0, ,
     4.319 | Remote._get_fetch_info_from_stderr 5
     4.449 | Remote._get_fetch_info_from_stderr 3
     4.449 | Remote._get_fetch_info_from_stderr 4
remote: Compressing objects: 100% (99/99), done.        er(remote: Compressing objects:   1% (1/99)
)
remote: Compressing objects: 100% (99/99), done.    ote: Compressing objects:   1% (1/99)
     4.449 | update 9, 1.0, 99.0,
     4.449 | update 8, 2.0, 99.0,
     4.450 | update 8, 3.0, 99.0,
     4.450 | update 8, 4.0, 99.0,
     4.450 | update 8, 5.0, 99.0,
     4.450 | update 8, 6.0, 99.0,
     4.450 | update 8, 7.0, 99.0,
     4.450 | update 8, 8.0, 99.0,
     4.450 | update 8, 9.0, 99.0,
     4.450 | update 8, 10.0, 99.0,
     4.450 | update 8, 11.0, 99.0,
     4.450 | update 8, 12.0, 99.0,
     4.450 | update 8, 13.0, 99.0,
     4.450 | update 8, 14.0, 99.0,
     4.450 | update 8, 15.0, 99.0,
     4.450 | update 8, 16.0, 99.0,
     4.450 | update 8, 17.0, 99.0,
     4.450 | update 8, 18.0, 99.0,
     4.450 | update 8, 19.0, 99.0,
     4.450 | update 8, 20.0, 99.0,
     4.450 | update 8, 21.0, 99.0,
     4.450 | update 8, 22.0, 99.0,
     4.450 | update 8, 23.0, 99.0,
     4.451 | update 8, 24.0, 99.0,
     4.451 | update 8, 25.0, 99.0,
     4.451 | update 8, 26.0, 99.0,
     4.451 | update 8, 27.0, 99.0,
     4.451 | update 8, 28.0, 99.0,
     4.451 | update 8, 29.0, 99.0,
     4.451 | update 8, 30.0, 99.0,
     4.451 | update 8, 31.0, 99.0,
     4.451 | update 8, 32.0, 99.0,
     4.451 | update 8, 33.0, 99.0,
     4.451 | update 8, 34.0, 99.0,
     4.451 | update 8, 35.0, 99.0,
     4.451 | update 8, 36.0, 99.0,
     4.451 | update 8, 37.0, 99.0,
     4.451 | update 8, 38.0, 99.0,
     4.451 | update 8, 39.0, 99.0,
     4.451 | update 8, 40.0, 99.0,
     4.451 | update 8, 41.0, 99.0,
     4.451 | update 8, 42.0, 99.0,
     4.451 | update 8, 43.0, 99.0,
     4.451 | update 8, 44.0, 99.0,
     4.451 | update 8, 45.0, 99.0,
     4.452 | update 8, 46.0, 99.0,
     4.452 | update 8, 47.0, 99.0,
     4.452 | update 8, 48.0, 99.0,
     4.452 | update 8, 49.0, 99.0,
     4.452 | update 8, 50.0, 99.0,
     4.452 | update 8, 51.0, 99.0,
     4.452 | update 8, 52.0, 99.0,
     4.452 | update 8, 53.0, 99.0,
     4.452 | update 8, 54.0, 99.0,
     4.452 | update 8, 55.0, 99.0,
     4.452 | update 8, 56.0, 99.0,
     4.452 | update 8, 57.0, 99.0,
     4.452 | update 8, 58.0, 99.0,
     4.452 | update 8, 59.0, 99.0,
     4.452 | update 8, 60.0, 99.0,
     4.452 | update 8, 61.0, 99.0,
     4.452 | update 8, 62.0, 99.0,
     4.452 | update 8, 63.0, 99.0,
     4.452 | update 8, 64.0, 99.0,
     4.452 | update 8, 65.0, 99.0,
     4.452 | update 8, 66.0, 99.0,
     4.452 | update 8, 67.0, 99.0,
     4.453 | update 8, 68.0, 99.0,
     4.453 | update 8, 69.0, 99.0,
     4.453 | update 8, 70.0, 99.0,
     4.453 | update 8, 71.0, 99.0,
     4.453 | update 8, 72.0, 99.0,
     4.453 | update 8, 73.0, 99.0,
     4.453 | update 8, 74.0, 99.0,
     4.453 | update 8, 75.0, 99.0,
     4.453 | update 8, 76.0, 99.0,
     4.453 | update 8, 77.0, 99.0,
     4.453 | update 8, 78.0, 99.0,
     4.453 | update 8, 79.0, 99.0,
     4.453 | update 8, 80.0, 99.0,
     4.453 | update 8, 81.0, 99.0,
     4.453 | update 8, 82.0, 99.0,
     4.453 | update 8, 83.0, 99.0,
     4.453 | update 8, 84.0, 99.0,
     4.453 | update 8, 85.0, 99.0,
     4.453 | update 8, 86.0, 99.0,
     4.453 | update 8, 87.0, 99.0,
     4.453 | update 8, 88.0, 99.0,
     4.454 | update 8, 89.0, 99.0,
     4.454 | update 8, 90.0, 99.0,
     4.454 | update 8, 91.0, 99.0,
     4.454 | update 8, 92.0, 99.0,
     4.454 | update 8, 93.0, 99.0,
     4.454 | update 8, 94.0, 99.0,
     4.454 | update 8, 95.0, 99.0,
     4.454 | update 8, 96.0, 99.0,
     4.454 | update 8, 97.0, 99.0,
     4.454 | update 8, 98.0, 99.0,
     4.454 | update 8, 99.0, 99.0,
     4.454 | update 10, 99.0, 99.0,
     4.454 | Remote._get_fetch_info_from_stderr 5
    12.761 | Remote._get_fetch_info_from_stderr 3
    12.761 | Remote._get_fetch_info_from_stderr 4
remote: Total 10334 (delta 68), reused 9 (delta 9), pack-reused 10224           0% (1/10334)
)
remote: Total 10334 (delta 68), reused 9 (delta 9), pack-reused 10224 0% (1/10334)
    12.761 | update 33, 1.0, 10334.0,
    12.761 | update 32, 104.0, 10334.0,
    12.761 | update 32, 207.0, 10334.0,
    12.761 | update 32, 311.0, 10334.0,
    12.761 | update 32, 414.0, 10334.0,
    12.761 | update 32, 517.0, 10334.0, , 236.00 KiB | 448.00 KiB/s
    12.761 | update 32, 621.0, 10334.0, , 236.00 KiB | 448.00 KiB/s
    12.761 | update 32, 724.0, 10334.0, , 236.00 KiB | 448.00 KiB/s
    12.761 | update 32, 827.0, 10334.0, , 236.00 KiB | 448.00 KiB/s
    12.761 | update 32, 931.0, 10334.0, , 236.00 KiB | 448.00 KiB/s
    12.761 | update 32, 1034.0, 10334.0, , 236.00 KiB | 448.00 KiB/s
    12.761 | update 32, 1116.0, 10334.0, , 652.00 KiB | 623.00 KiB/s
    12.762 | update 32, 1137.0, 10334.0, , 652.00 KiB | 623.00 KiB/s
    12.762 | update 32, 1241.0, 10334.0, , 652.00 KiB | 623.00 KiB/s
    12.762 | update 32, 1344.0, 10334.0, , 652.00 KiB | 623.00 KiB/s
    12.762 | update 32, 1447.0, 10334.0, , 652.00 KiB | 623.00 KiB/s
    12.762 | update 32, 1551.0, 10334.0, , 652.00 KiB | 623.00 KiB/s
    12.762 | update 32, 1654.0, 10334.0, , 652.00 KiB | 623.00 KiB/s
    12.762 | update 32, 1757.0, 10334.0, , 652.00 KiB | 623.00 KiB/s
    12.762 | update 32, 1861.0, 10334.0, , 652.00 KiB | 623.00 KiB/s
    12.762 | update 32, 1964.0, 10334.0, , 1.20 MiB | 787.00 KiB/s
    12.762 | update 32, 2067.0, 10334.0, , 1.20 MiB | 787.00 KiB/s
    12.762 | update 32, 2171.0, 10334.0, , 1.20 MiB | 787.00 KiB/s
    12.762 | update 32, 2274.0, 10334.0, , 1.20 MiB | 787.00 KiB/s
    12.762 | update 32, 2377.0, 10334.0, , 1.20 MiB | 787.00 KiB/s
    12.762 | update 32, 2481.0, 10334.0, , 1.20 MiB | 787.00 KiB/s
    12.762 | update 32, 2572.0, 10334.0, , 1.20 MiB | 787.00 KiB/s
    12.762 | update 32, 2584.0, 10334.0, , 1.20 MiB | 787.00 KiB/s
    12.762 | update 32, 2687.0, 10334.0, , 1.69 MiB | 833.00 KiB/s
    12.762 | update 32, 2791.0, 10334.0, , 1.69 MiB | 833.00 KiB/s
    12.762 | update 32, 2894.0, 10334.0, , 1.69 MiB | 833.00 KiB/s
    12.762 | update 32, 2997.0, 10334.0, , 1.69 MiB | 833.00 KiB/s
    12.763 | update 32, 3101.0, 10334.0, , 1.69 MiB | 833.00 KiB/s
    12.763 | update 32, 3204.0, 10334.0, , 1.69 MiB | 833.00 KiB/s
    12.763 | update 32, 3307.0, 10334.0, , 1.69 MiB | 833.00 KiB/s
    12.763 | update 32, 3411.0, 10334.0, , 1.69 MiB | 833.00 KiB/s
    12.763 | update 32, 3514.0, 10334.0, , 1.69 MiB | 833.00 KiB/s
    12.763 | update 32, 3617.0, 10334.0, , 1.69 MiB | 833.00 KiB/s
    12.763 | update 32, 3721.0, 10334.0, , 1.69 MiB | 833.00 KiB/s
    12.763 | update 32, 3824.0, 10334.0, , 1.69 MiB | 833.00 KiB/s
    12.763 | update 32, 3927.0, 10334.0, , 1.69 MiB | 833.00 KiB/s
    12.763 | update 32, 4031.0, 10334.0, , 1.69 MiB | 833.00 KiB/s
    12.763 | update 32, 4134.0, 10334.0, , 1.69 MiB | 833.00 KiB/s
    12.763 | update 32, 4237.0, 10334.0, , 1.69 MiB | 833.00 KiB/s
    12.763 | update 32, 4341.0, 10334.0, , 2.07 MiB | 813.00 KiB/s
    12.763 | update 32, 4444.0, 10334.0, , 2.07 MiB | 813.00 KiB/s
    12.763 | update 32, 4547.0, 10334.0, , 2.07 MiB | 813.00 KiB/s
    12.763 | update 32, 4651.0, 10334.0, , 2.07 MiB | 813.00 KiB/s
    12.763 | update 32, 4742.0, 10334.0, , 2.07 MiB | 813.00 KiB/s
    12.763 | update 32, 4754.0, 10334.0, , 2.07 MiB | 813.00 KiB/s
    12.763 | update 32, 4857.0, 10334.0, , 2.07 MiB | 813.00 KiB/s
    12.763 | update 32, 4961.0, 10334.0, , 2.07 MiB | 813.00 KiB/s
    12.764 | update 32, 5064.0, 10334.0, , 3.00 MiB | 831.00 KiB/s
    12.764 | update 32, 5167.0, 10334.0, , 3.00 MiB | 831.00 KiB/s
    12.764 | update 32, 5249.0, 10334.0, , 3.00 MiB | 831.00 KiB/s
    12.764 | update 32, 5271.0, 10334.0, , 3.00 MiB | 831.00 KiB/s
    12.764 | update 32, 5374.0, 10334.0, , 3.00 MiB | 831.00 KiB/s
    12.764 | update 32, 5478.0, 10334.0, , 3.00 MiB | 831.00 KiB/s
    12.764 | update 32, 5581.0, 10334.0, , 3.50 MiB | 825.00 KiB/s
    12.764 | update 32, 5684.0, 10334.0, , 3.50 MiB | 825.00 KiB/s
    12.764 | update 32, 5788.0, 10334.0, , 3.50 MiB | 825.00 KiB/s
    12.764 | update 32, 5891.0, 10334.0, , 3.50 MiB | 825.00 KiB/s
    12.764 | update 32, 5994.0, 10334.0, , 3.50 MiB | 825.00 KiB/s
    12.764 | update 32, 6098.0, 10334.0, , 4.00 MiB | 842.00 KiB/s
    12.764 | update 32, 6201.0, 10334.0, , 4.00 MiB | 842.00 KiB/s
    12.764 | update 32, 6262.0, 10334.0, , 4.00 MiB | 842.00 KiB/s
    12.764 | update 32, 6304.0, 10334.0, , 4.00 MiB | 842.00 KiB/s
    12.764 | update 32, 6408.0, 10334.0, , 4.00 MiB | 842.00 KiB/s
    12.764 | update 32, 6511.0, 10334.0, , 4.00 MiB | 842.00 KiB/s
    12.764 | update 32, 6614.0, 10334.0, , 4.38 MiB | 866.00 KiB/s
    12.764 | update 32, 6718.0, 10334.0, , 4.38 MiB | 866.00 KiB/s
    12.764 | update 32, 6821.0, 10334.0, , 4.38 MiB | 866.00 KiB/s
    12.764 | update 32, 6924.0, 10334.0, , 4.38 MiB | 866.00 KiB/s
    12.765 | update 32, 7028.0, 10334.0, , 4.38 MiB | 866.00 KiB/s
    12.765 | update 32, 7131.0, 10334.0, , 4.38 MiB | 866.00 KiB/s
    12.765 | update 32, 7234.0, 10334.0, , 4.38 MiB | 866.00 KiB/s
    12.765 | update 32, 7338.0, 10334.0, , 4.38 MiB | 866.00 KiB/s
    12.765 | update 32, 7441.0, 10334.0, , 4.38 MiB | 866.00 KiB/s
    12.765 | update 32, 7544.0, 10334.0, , 4.38 MiB | 866.00 KiB/s
    12.765 | update 32, 7648.0, 10334.0, , 4.38 MiB | 866.00 KiB/s
    12.765 | update 32, 7751.0, 10334.0, , 4.38 MiB | 866.00 KiB/s
    12.765 | update 32, 7854.0, 10334.0, , 4.38 MiB | 866.00 KiB/s
    12.765 | update 32, 7958.0, 10334.0, , 4.38 MiB | 866.00 KiB/s
    12.765 | update 32, 8061.0, 10334.0, , 4.38 MiB | 866.00 KiB/s
    12.765 | update 32, 8164.0, 10334.0, , 4.38 MiB | 866.00 KiB/s
    12.765 | update 32, 8268.0, 10334.0, , 4.75 MiB | 859.00 KiB/s
    12.765 | update 32, 8314.0, 10334.0, , 4.75 MiB | 859.00 KiB/s
    12.765 | update 32, 8371.0, 10334.0, , 4.75 MiB | 859.00 KiB/s
    12.765 | update 32, 8474.0, 10334.0, , 4.75 MiB | 859.00 KiB/s
    12.765 | update 32, 8578.0, 10334.0, , 4.75 MiB | 859.00 KiB/s
    12.765 | update 32, 8681.0, 10334.0, , 5.00 MiB | 793.00 KiB/s
    12.765 | update 32, 8784.0, 10334.0, , 5.00 MiB | 793.00 KiB/s
    12.765 | update 32, 8888.0, 10334.0, , 5.00 MiB | 793.00 KiB/s
    12.766 | update 32, 8991.0, 10334.0, , 5.00 MiB | 793.00 KiB/s
    12.766 | update 32, 9094.0, 10334.0, , 5.00 MiB | 793.00 KiB/s
    12.766 | update 32, 9198.0, 10334.0, , 5.00 MiB | 793.00 KiB/s
    12.766 | update 32, 9217.0, 10334.0, , 5.29 MiB | 744.00 KiB/s
    12.766 | update 32, 9301.0, 10334.0, , 5.29 MiB | 744.00 KiB/s
    12.766 | update 32, 9404.0, 10334.0, , 5.29 MiB | 744.00 KiB/s
    12.766 | update 32, 9508.0, 10334.0, , 5.29 MiB | 744.00 KiB/s
    12.766 | update 32, 9611.0, 10334.0, , 5.29 MiB | 744.00 KiB/s
    12.766 | update 32, 9714.0, 10334.0, , 5.29 MiB | 744.00 KiB/s
    12.766 | update 32, 9818.0, 10334.0, , 5.60 MiB | 708.00 KiB/s
    12.766 | update 32, 9921.0, 10334.0, , 5.60 MiB | 708.00 KiB/s
    12.766 | update 32, 10024.0, 10334.0, , 5.60 MiB | 708.00 KiB/s
    12.766 | update 32, 10114.0, 10334.0, , 5.60 MiB | 708.00 KiB/s
    12.766 | update 32, 10128.0, 10334.0, , 5.60 MiB | 708.00 KiB/s
    12.766 | update 32, 10231.0, 10334.0, , 5.60 MiB | 708.00 KiB/s
    12.766 | RemoteProgress.line_dropped
    12.766 | Remote._get_fetch_info_from_stderr 5
    12.766 | Remote._get_fetch_info_from_stderr 3
    12.766 | Remote._get_fetch_info_from_stderr 4
Receiving objects: 100% (10334/10334), 5.93 MiB | 647.00 KiB/s, done.objects: 100% (10334/10334), 5.88 MiB | 677.00 KiB/s
)
Receiving objects: 100% (10334/10334), 5.93 MiB | 647.00 KiB/s, done.00% (10334/10334), 5.88 MiB | 677.00 KiB/s
    12.769 | update 32, 10334.0, 10334.0, , 5.88 MiB | 677.00 KiB/s
    12.769 | update 34, 10334.0, 10334.0, , 5.93 MiB | 647.00 KiB/s
    12.769 | Remote._get_fetch_info_from_stderr 5
    12.838 | Remote._get_fetch_info_from_stderr 3
    12.839 | Remote._get_fetch_info_from_stderr 4
Resolving deltas: 100% (5914/5914), done.andler()::handler(Resolving deltas:   0% (0/5914)
)
Resolving deltas: 100% (5914/5914), done.ss_line Resolving deltas:   0% (0/5914)
    12.839 | update 65, 0.0, 5914.0,
    12.839 | update 64, 60.0, 5914.0,
    12.839 | update 64, 122.0, 5914.0,
    12.839 | update 64, 188.0, 5914.0,
    12.839 | update 64, 245.0, 5914.0,
    12.839 | update 64, 308.0, 5914.0,
    12.839 | update 64, 356.0, 5914.0,
    12.839 | update 64, 419.0, 5914.0,
    12.839 | update 64, 481.0, 5914.0,
    12.839 | update 64, 539.0, 5914.0,
    12.839 | update 64, 599.0, 5914.0,
    12.839 | update 64, 661.0, 5914.0,
    12.839 | update 64, 726.0, 5914.0,
    12.839 | update 64, 774.0, 5914.0,
    12.839 | update 64, 832.0, 5914.0,
    12.839 | update 64, 888.0, 5914.0,
    12.839 | update 64, 964.0, 5914.0,
    12.839 | update 64, 1018.0, 5914.0,
    12.839 | update 64, 1069.0, 5914.0,
    12.839 | update 64, 1125.0, 5914.0,
    12.839 | update 64, 1192.0, 5914.0,
    12.839 | update 64, 1243.0, 5914.0,
    12.839 | update 64, 1313.0, 5914.0,
    12.840 | update 64, 1361.0, 5914.0,
    12.840 | update 64, 1423.0, 5914.0,
    12.840 | update 64, 1482.0, 5914.0,
    12.840 | update 64, 1547.0, 5914.0,
    12.840 | update 64, 1600.0, 5914.0,
    12.840 | update 64, 1657.0, 5914.0,
    12.840 | update 64, 1718.0, 5914.0,
    12.840 | update 64, 1778.0, 5914.0,
    12.840 | update 64, 1839.0, 5914.0,
    12.840 | update 64, 1905.0, 5914.0,
    12.840 | update 64, 1955.0, 5914.0,
    12.840 | update 64, 2011.0, 5914.0,
    12.840 | update 64, 2083.0, 5914.0,
    12.840 | update 64, 2135.0, 5914.0,
    12.840 | update 64, 2193.0, 5914.0,
    12.840 | update 64, 2249.0, 5914.0,
    12.840 | update 64, 2333.0, 5914.0,
    12.840 | update 64, 2368.0, 5914.0,
    12.840 | update 64, 2429.0, 5914.0,
    12.840 | update 64, 2507.0, 5914.0,
    12.840 | update 64, 2565.0, 5914.0,
    12.840 | update 64, 2604.0, 5914.0,
    12.840 | update 64, 2675.0, 5914.0,
    12.840 | update 64, 2721.0, 5914.0,
    12.840 | update 64, 2795.0, 5914.0,
    12.840 | update 64, 2840.0, 5914.0,
    12.840 | update 64, 2935.0, 5914.0,
    12.840 | update 64, 2966.0, 5914.0,
    12.841 | update 64, 3021.0, 5914.0,
    12.841 | update 64, 3083.0, 5914.0,
    12.841 | update 64, 3139.0, 5914.0,
    12.841 | update 64, 3225.0, 5914.0,
    12.841 | update 64, 3261.0, 5914.0,
    12.841 | update 64, 3315.0, 5914.0,
    12.841 | update 64, 3382.0, 5914.0,
    12.841 | update 64, 3438.0, 5914.0,
    12.841 | update 64, 3493.0, 5914.0,
    12.841 | update 64, 3641.0, 5914.0,
    12.841 | update 64, 3693.0, 5914.0,
    12.841 | update 64, 3740.0, 5914.0,
    12.841 | update 64, 3785.0, 5914.0,
    12.841 | update 64, 3861.0, 5914.0,
    12.841 | update 64, 3935.0, 5914.0,
    12.841 | update 64, 3973.0, 5914.0,
    12.841 | update 64, 4035.0, 5914.0,
    12.841 | update 64, 4095.0, 5914.0,
    12.841 | update 64, 4140.0, 5914.0,
    12.841 | update 64, 4199.0, 5914.0,
    12.841 | update 64, 4259.0, 5914.0,
    12.841 | update 64, 4318.0, 5914.0,
    12.841 | update 64, 4377.0, 5914.0,
    12.841 | update 64, 4449.0, 5914.0,
    12.841 | update 64, 4496.0, 5914.0,
    12.841 | update 64, 4582.0, 5914.0,
    12.841 | update 64, 4617.0, 5914.0,
    12.841 | update 64, 4736.0, 5914.0,
    12.841 | update 64, 4795.0, 5914.0,
    12.842 | update 64, 4850.0, 5914.0,
    12.842 | update 64, 4910.0, 5914.0,
    12.842 | update 64, 4978.0, 5914.0,
    12.842 | update 64, 5027.0, 5914.0,
    12.842 | update 64, 5088.0, 5914.0,
    12.842 | update 64, 5155.0, 5914.0,
    12.842 | update 64, 5205.0, 5914.0,
    12.842 | update 64, 5269.0, 5914.0,
    12.842 | update 64, 5340.0, 5914.0,
    12.842 | update 64, 5382.0, 5914.0,
    12.842 | update 64, 5466.0, 5914.0,
    12.842 | update 64, 5502.0, 5914.0,
    12.842 | update 64, 5564.0, 5914.0,
    12.842 | update 64, 5621.0, 5914.0,
    12.845 | update 64, 5687.0, 5914.0,
    12.845 | update 64, 5737.0, 5914.0,
    12.845 | update 64, 5796.0, 5914.0,
    12.845 | update 64, 5864.0, 5914.0,
    12.845 | update 64, 5914.0, 5914.0,
    12.845 | update 66, 5914.0, 5914.0,
    12.845 | Remote._get_fetch_info_from_stderr 5
    13.159 | Remote._get_fetch_info_from_stderr 3
    13.159 | Remote._get_fetch_info_from_stderr 4
    13.159 | RemoteProgress.new_message_handler()::handler(From github.com:gitpython-developers/GitPython
)
    13.159 | RemoteProgress._parse_progress_line From github.com:gitpython-developers/GitPython
    13.159 | RemoteProgress.line_dropped
    13.159 | Remote._get_fetch_info_from_stderr 5
    13.159 | Remote._get_fetch_info_from_stderr 3
    13.159 | Remote._get_fetch_info_from_stderr 4
    13.159 | RemoteProgress.new_message_handler()::handler( * branch            master     -> FETCH_HEAD
)
    13.160 | RemoteProgress._parse_progress_line  * branch            master     -> FETCH_HEAD
    13.160 | RemoteProgress.line_dropped
    13.160 | Remote._get_fetch_info_from_stderr 5
    13.160 | Remote._get_fetch_info_from_stderr 3
    13.160 | Remote._get_fetch_info_from_stderr 4
    13.160 | RemoteProgress.new_message_handler()::handler( * [new branch]      master     -> github/master
)
    13.160 | RemoteProgress._parse_progress_line  * [new branch]      master     -> github/master
    13.160 | RemoteProgress.line_dropped
    13.160 | Remote._get_fetch_info_from_stderr 5
    13.189 | Remote._get_fetch_info_from_stderr 6
Fetch head lines do not match lines provided via progress information
length of progress lines 2 should be equal to lines in FETCH_HEAD file 1
Will ignore extra progress lines or fetch head lines.

Successfully cloned `https://github.com/gitpython-developers/GitPython` into `./GitPython`!

What I'm thinking is that there's another issue here, and it's that the python file object might be iterating over \n, but progress is mostly shown using \r by git. Thus, it's only updating the output a couple of times with big pauses because it's not returning each line ending with \r (that might actually explain the error shown). We'd need to check whether how the stderr file object is being configured by subprocess and whether it explicitly disables universal line ending mode.

Byron · 2016-05-26T17:10:59Z

Maybe ioctl can be used to configure the handle after it was created. Or there is a way to do that where the process is spawned.

guyzmo · 2016-05-26T17:18:29Z

I think I'm onto something, I stopped with pdb to watch at the type of proc.stderr, and found out that proc.stderr.mode is 'rb', so it's binary buffering, and it's unlikely to have universal line ending enabled.

Then I went on to read subprocess documentation where it says:

Popen.stderr

If the stderr argument was PIPE, this attribute is a readable stream object as returned by open(). Reading from the stream provides error output from the child process. If the universal_newlines argument was True, the stream is a text stream, otherwise it is a byte stream. If the stderr argument was not PIPE, this attribute is None.

so I guess it's worth trying with Popen(..., universal_newlines=True)!

guyzmo · 2016-05-26T17:31:22Z

yay, it's what was the issue \o/

http:https://asciinema.org/a/5n0tyv6jmvu14u8lsi18f53c5

there's a bunch of caveats, though, because now proc.stderr lines are not bytes anymore, but unicode str.

Byron · 2016-05-26T17:33:31Z

Looks very good ! I am currently experimenting with adding this option just for fetch/push operations, and it doesn't seem too straightforward for some reason. Let's see how it goes.

guyzmo · 2016-05-26T17:33:38Z

Though, as a side effect the fetching is quite terribly slow, certainly of the overhead of going twice to stdout.

Byron · 2016-05-26T17:34:59Z

Why is it going through stdout twice ? And even if so, it's just a few hundred lines at most, and I wouldn't expect this to be noticeable. If it is, it might be something with regular expressions being slow ? Just guessing though.

guyzmo · 2016-05-26T17:36:40Z

well, from git's stdout to GitPython, and from GitPython to stdout!

Byron · 2016-05-26T17:38:12Z

That is something I would then consider a bug in either codebase, and hopefully fixable.

guyzmo · 2016-05-26T17:38:15Z

here's a summary of my patch:

modified: git/cmd.py
@@ -608,6 +608,7 @@ class Git(LazyMixin):
                          stdout=with_stdout and PIPE or open(os.devnull, 'wb'),
                          shell=self.USE_SHELL,
                          close_fds=(os.name == 'posix'),  # unsupported on windows
+                         universal_newlines=True,
                          **subprocess_kwargs
                          )
         except cmd_not_found_exception as err:
@@ -661,18 +662,15 @@ class Git(LazyMixin):
                         stderr_value = 'Timeout: the command "%s" did not complete in %d ' \
                                        'secs.' % (" ".join(command), kill_after_timeout)
                 # strip trailing "\n"
-                if stdout_value.endswith(b"\n"):
-                    stdout_value = stdout_value[:-1]
-                if stderr_value.endswith(b"\n"):
-                    stderr_value = stderr_value[:-1]
+                stdout_value = stdout_value.rstrip('\n')
+                stderr_value = stdout_value.rstrip('\n')
                 status = proc.returncode
             else:
                 stream_copy(proc.stdout, output_stream, self.max_chunk_size)
                 stdout_value = output_stream
                 stderr_value = proc.stderr.read()
                 # strip trailing "\n"
-                if stderr_value.endswith(b"\n"):
-                    stderr_value = stderr_value[:-1]
+                stderr_value = stdout_value.rstrip('\n')
                 status = proc.wait()
             # END stdout handling
         finally:

modified: git/remote.py
@@ -564,8 +564,9 @@ class Remote(LazyMixin, Iterable):

         progress_handler = progress.new_message_handler()

-        for line in proc.stderr.readlines():
-            line = line.decode(defenc)
+        for line in proc.stderr:
             for pline in progress_handler(line):
                 if line.startswith('fatal:') or line.startswith('error:'):
                     raise GitCommandError(("Error when fetching: %s" % line,), 2)

about the other errors, I just found out that I fscked up my local workspace, so to make a proper commit I need to do some cleaning first :)

That way, real-time parsing of output should finally be possible. Related to #444

Byron · 2016-05-26T17:44:02Z

I just pushed the universal_newline fix for remote operations. It should work, but please verify. For anything, I'd be happy to merge PRs you send this way.

Thanks for the asciicinema videos, it was nice to see the results of this work, and certainly helped my motivations :) !

Related to #444

Byron · 2016-05-26T17:55:30Z

I think this is fixed now:

GitPython/git/remote.py

Line 553 in 902679c

for line in proc.stderr:

.

guyzmo · 2016-05-26T17:59:48Z

ok, it looks like the "slowness" of my pulls might be caused by github throttling me, as I'm hammering them a bit too much:

git clone -v --progress https://github.com/gitpython-developers/GitPython  0.72s user 0.23s system 3% cpu 26.830 total
git hub -v clone gitpython-developers/GitPython  1.28s user 0.19s system 6% cpu 24.252 total

as I'm on a gigabit connection, I'm used to the clone being a lot less :)

barry-scott · 2016-10-11T18:14:40Z

@Byron I thought this was fixed. I'm not seeing the problem any more. Can this issue me closed?

guyzmo · 2016-10-11T20:29:25Z

worksforme ☺

ankostis · 2016-10-11T20:41:17Z

We can close it then, fixed under the milestone it is currently under!
Thanks.

(do you want to push any AUTHOR changes?)

guyzmo · 2016-10-11T21:34:39Z

sure thanks, I'll do that in a currently pending PR I'm pushing!

mrozekma · 2017-08-06T18:29:54Z

Not sure if I should file a new bug or resurrect this one, but an earlier comment says:

I am currently experimenting with adding this option just for fetch/push operations

Was cloning just overlooked? git.Repo.clone_from seems to have the exact same problem. I fixed it locally by changing git.remote.add_progress to also set kwargs['universal_newlines'] = True, and changing git.base.Repo._clone to pass decode_streams = False to handle_process_output

Byron · 2017-09-28T14:47:54Z

@mrozekma I believe creating a new issue would be the way to go, while assuring the issue can be reproduced with the latest version.

guyzmo mentioned this issue May 26, 2016

Improve progress bar reporting guyzmo/git-repo#15

Closed

Byron added the Q&A label May 26, 2016

Byron added the waiting for feedback label May 26, 2016

Byron added acknowledged and removed waiting for feedback labels May 26, 2016

Byron self-assigned this May 26, 2016

Byron added this to the v2.0.4 - Bugfixes milestone May 26, 2016

Byron removed the Q&A label May 26, 2016

Byron closed this as completed in 04ff96d May 26, 2016

Byron reopened this May 26, 2016

Byron added a commit that referenced this issue May 26, 2016

fix(remote): use universal_newlines for fetch/push

515a6b9

That way, real-time parsing of output should finally be possible. Related to #444

Byron added the waiting for feedback label May 26, 2016

Byron added a commit that referenced this issue May 26, 2016

fix(remote): py3 compatibility

902679c

Related to #444

nvie modified the milestones: v2.0.4 - Bugfixes, v2.0.5, v2.0.5 - Bugfixes, v2.0.6 - Bugfixes May 30, 2016

guyzmo mentioned this issue Jun 8, 2016

Why is progress an object and not a function? #436

Closed

nvie modified the milestones: v2.0.6 - Bugfixes, v2.0.7 - Bugfixes Jun 20, 2016

Byron modified the milestones: v2.0.7 - Bugfixes, v2.0.8 - Bugfixes Jul 17, 2016

Byron removed their assignment Jul 23, 2016

Byron modified the milestones: v2.0.8 - Bugfixes, v2.0.9 - Bugfixes Aug 3, 2016

guyzmo closed this as completed Oct 11, 2016

Minipada mentioned this issue Oct 7, 2017

clone_from progress is broken in newer version #604

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Progress not showing up before the last second #444

Progress not showing up before the last second #444

guyzmo commented May 26, 2016

Byron commented May 26, 2016

guyzmo commented May 26, 2016

guyzmo commented May 26, 2016

Byron commented May 26, 2016

guyzmo commented May 26, 2016

Byron commented May 26, 2016 •

edited

Loading

guyzmo commented May 26, 2016

guyzmo commented May 26, 2016

Byron commented May 26, 2016

guyzmo commented May 26, 2016

Byron commented May 26, 2016

guyzmo commented May 26, 2016

Byron commented May 26, 2016

guyzmo commented May 26, 2016 •

edited

Loading

Byron commented May 26, 2016

Byron commented May 26, 2016

guyzmo commented May 26, 2016

barry-scott commented Oct 11, 2016

guyzmo commented Oct 11, 2016

ankostis commented Oct 11, 2016

guyzmo commented Oct 11, 2016

mrozekma commented Aug 6, 2017

Byron commented Sep 28, 2017

Progress not showing up before the last second #444

Progress not showing up before the last second #444

Comments

guyzmo commented May 26, 2016

Byron commented May 26, 2016

guyzmo commented May 26, 2016

guyzmo commented May 26, 2016

Byron commented May 26, 2016

guyzmo commented May 26, 2016

Byron commented May 26, 2016 • edited Loading

guyzmo commented May 26, 2016

guyzmo commented May 26, 2016

Byron commented May 26, 2016

guyzmo commented May 26, 2016

Byron commented May 26, 2016

guyzmo commented May 26, 2016

Byron commented May 26, 2016

guyzmo commented May 26, 2016 • edited Loading

Byron commented May 26, 2016

Byron commented May 26, 2016

guyzmo commented May 26, 2016

barry-scott commented Oct 11, 2016

guyzmo commented Oct 11, 2016

ankostis commented Oct 11, 2016

guyzmo commented Oct 11, 2016

mrozekma commented Aug 6, 2017

Byron commented Sep 28, 2017

Byron commented May 26, 2016 •

edited

Loading

guyzmo commented May 26, 2016 •

edited

Loading