Batches of n by rubyist · Pull Request #476 · git-lfs/git-lfs · GitHub
Skip to content

Batches of n - #476

Merged
rubyist merged 25 commits into
masterfrom
batches-of-n
Jul 29, 2015
Merged

rubyist merged 25 commits into
masterfrom
batches-of-n

Conversation

@rubyist

@rubyist rubyist commented Jul 9, 2015

Copy link
Copy Markdown
Contributor

This PR splits up batch requests into several batches of n (currently hardcoded to 100).

  • Progress counters are a little off
  • Handle errors to the batch call, resubmit batch or track failures
  • Test with many thousands of files

@rubyist rubyist added the wip label Jul 9, 2015
rubyist added 14 commits July 9, 2015 17:09
This removes the `pb` based progress bar for the transfer queue and add
a simpler custom bar. pb really wants to know total counts and byte
sizes up front but when doing batches of n we would prefer to not know
that. This is due to the fact that the batcher will block until it is
drained instead of processing all pointers and storing them in memory
while transfer operations run. This also clarifies when files are
skipped because the server already has them. Progress output here
contains the number of finished transfers/bytes, the number of
transfers/bytes currently in the queue, and the number of files skipped,
if any.
Go back to requiring a count and size up front, but better track and
display files that are skipped because they don't need to transfer. This
makes it easier to judge what is happening based on the progress output.
@rubyist rubyist added review and removed wip labels Jul 27, 2015
@rubyist

rubyist commented Jul 27, 2015

Copy link
Copy Markdown
Contributor Author

Comment thread lfs/transfer_queue.go Outdated

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

"feed" => "fed"

@technoweenie

Copy link
Copy Markdown
Contributor

This is looking much better. I can't wait to kill all the legacy api client stuff for v0.7.0 🤘

A couple things come to mind while reading this:

  1. It looks like TransferQueue will work to drain the batcher's queue as fast as possible. It doesn't seem to wait for every item in the batch to transfer before grabbing the next batch of 100.
  2. Errors seem to collect forever. I wonder if TransferQueue should halt early if there are enough errors.
  3. It doesn't look like there's a way for the TransferQueue to retry failed transfers. We may want to look for common transient errors that can safely be retried.
  4. How does this affect the CopyCallback stuff? Will native apps still get a reasonably accurate progress log?

@rubyist

rubyist commented Jul 27, 2015

Copy link
Copy Markdown
Contributor Author
  1. It will only drain 100 at a time. The channel that feeds transfers from batchApiRoutine() to transferWorker() has a batchSize buffer (ie 100). It will fill that up then block until a transfer is completed. batchApiRoutine() only calls batcher.Next() once all of the objects from that batch request have been sent to the transferWorker. As transfers from batch A finish, transfers from batch B will trickle into the queue, but batch C won't be requested until batch B is drained, effectively preventing it from draining any faster. I can add some commenting around that code to make the blocking nature a little more clear.
  2. This is true, the batch code has always queued errors until the end. Now that we're realizing people are dealing with very large numbers of files we might want an early halt strategy and/or error counts in the progress output.
  3. This is also true, I almost added the ability to push failures back onto the batcher but thought it might go into a separate PR. I think it would go pretty cleanly along with the schema change that adds the errors properties.
  4. All of that stuff should still be intact, the progress meter writes out the log file for native apps, if the env var is set. I don't think we have a very strict test regarding the content of that file, though, I'll add one so we can make sure it continues to work.

@technoweenie

Copy link
Copy Markdown
Contributor
  1. Okay, I missed that q.transferc has a capacity of 100. My main concern is that the time between the batch api completing and the 100th file transferring could extend beyond the expiration timeout. Perhaps this is just something servers need to be aware of. If a user is uploading 100 1GB files, the server should send back a pretty ridiculously high expiration.

I would really like to track timestamps for this stuff. Maybe transferWorker() can report to tracerx how long it had to wait since the batch (or individual) API returned the link relation for that object. Could be useful for debugging.

I agree that 2 and 3 should go in separate PRs. I really want to add better testing for the CopyCallback for 4, but also not a concern of this PR.

@rubyist

rubyist commented Jul 27, 2015

Copy link
Copy Markdown
Contributor Author

rubyist added a commit that referenced this pull request Jul 29, 2015
@rubyist
rubyist merged commit bbd6dbc into master Jul 29, 2015
@rubyist
rubyist deleted the batches-of-n branch July 29, 2015 15:08
@technoweenie technoweenie mentioned this pull request Jul 30, 2015
chrisd8088 added a commit that referenced this pull request Aug 5, 2026
In PR #5504 we modified the CopyCallbackFile() method of the
GitFilter structure in our "lfs" package so that the callback
function it created only output a progress log message when
at least 200 milliseconds had elapsed since the last message
was written, unless the number of bytes read had met or exceeded
the total size of the given Git LFS object.  (The minimum time
allowed between messages was specified by the DefaultLoggingThrottle
constant from our "tasklog" package.)

This design depended on the assumption that the total size of the
given object was known and correct when the callback was utilized
by the CopyWithCallback() function of our "tools" package.  When
the "total" parameter was negative, though, a message would always
be written because the number of bytes read so far would always be
larger than the total size.

In a previous commit in this PR we adjusted the callback function
so that it now checks whether the value of the "total" parameter
is negative, and if so will not write a progress log message unless
a sufficient period of time has elapsed since the previous log
message was written.

However, one consequence of this adjustment is that when the "total"
parameter is negative, it is not guaranteed that a log message will
be written when the last callback is made after the final bytes of
the given object's data are read.  Further, if an object's data is
fully processed in less than 200 milliseconds, no progress log
message will be written for the object at all.

While it is currently rare for the value in the callback function's
"total" parameter to be negative, we expect it to become more common
in the future as a result of the bug fix to our "clean" filter
commands implemented by PR #6011.

PR #6011 resolves a bug in our "git lfs filter-progress" and
"git lfs clean" commands whereby they can pass an incorrect
"totalSize" parameter to the CopyWithCallback() function.  The only
solution for this problem is for the commands to simply not attempt
to determine the total size of an object.

Absent other changes, the result of this bug fix would be that
even if a progress log file is specified by the GIT_LFS_PROGRESS
environment variable, no messages would be written to the log file
during "clean" filter operations.  This would occur because the
copyToTemp() method of the GitFilter structure in our "lfs" package
would find a negative value in its "fileSize" parameter and then
set its "cb" callback function parameter to nil.

We intend to address this issue in PR #6011, but the consequence
when we do so will be that the callback function created by the
CopyCallbackFile() method will receive a negative value in its
"total" parameter during "clean" filter operations if a progress log
is configured with the GIT_LFS_PROGRESS environment variable.

At present, the callback function may already receive a negative
value in its "total" parameter, but only under a relatively unusual
combination of circumstances.  First, of course, a progress log must
be enabled with the GIT_LFS_PROGRESS environment variable.  Second,
the legacy "git lfs smudge" command must be used during a "smudge"
filter operation rather than the "git lfs filter-process" command;
this may occur if a version of Git older than v2.11.0 is in use.
Third, the "git lfs smudge" command must download an object that is
not available locally from a server which compresses the content
for transit and therefore sends a Content-Encoding header but no
Content-Length header.

Under these conditions, the lack of a Content-Length header means
the size of the HTTP response body will be represented with a value
of -1.  When our HTTP download adapter passes this negative value to
the CopyWithCallback() function, it will be used to initialize a new
CallbackReader structure from our "tools" package, and ultimately
passed to the callback function created by the CopyCallbackFile()
method.  Note that the callback function itself is passed from the
Smudge() method of the GitFilter structure to the same structure's
downloadFile() method, which creates a new transfer queue using
the WithProgressCallback() option function.

By contrast, when the "git lfs filter-process" command is in use,
it creates a transfer queue without a defined callback function.
As a result, objects that are not available locally are downloaded
and written to local storage without generating any progress log
messages.  When the Smudge() method is later invoked (because Git
re-sends a "smudge" command to our long-running filter process),
it runs the GitFilter structure's readLocalFile() method instead of
the downloadFile() method.  While the readLocalFile() method does
invoke the CopyWithCallback() function and passes a callback
function to it, at this point the size of the object can be
determined from the file in local storage, so the callback function
receives a non-negative value in its "total" parameter.

However, as described above, when the "git lfs smudge" command is
in use and a content-encoded download occurs, the callback function
created by the CopyCallbackFile() method will receive a negative
value in its "total" parameter, which means the function will write
to the progress log regardless of the amount of time that has
elapsed since the previous message was written.

Further, we expect the changes in PR #6011 to result in a wider
range of conditions under which the callback function will receive
a negative value in its "total" parameter.

We therefore now enhance both the callback function and the internal
implementation of the Read() method of the BodyWithCallback and
CallbackReader structures in our "tools" package so that a progress
log message will always be written when the final bytes of a given
object are read.

First, we update the doCallbackIfRequired() method of the
"callbackState" structure in our "tools" package so that it checks
if an EOF condition has been encountered, and if so, checks whether
the amount of data read so far exceeds the total size that was
provided initially for the given object.  Should both of these
conditions apply, the method resets the "totalSize" field of the
"callbackState" structure to the final value of the "readSize"
field, and then runs the doCallback() method to invoke the callback
function.

As a result of this change, a callback will be performed the first
time the EOF condition is encountered while processing an object
whose total size was initially unknown, and when this callback is
made, the callback function's "total" parameter will not have a
negative value but will have the same value as the function's
"written" parameter.

Next, we update the CopyCallbackFile() method of the GitFilter
structure in our "lfs" package so that the callback function the
method creates now checks whether the "total" parameter passed to
the function has a different value than it did the previous time
the function was invoked.  If this is the case, and if the current
value of the "total" is also equal to the non-negative value of the
"written" parameter, then the function writes a message to the
progress log regardless of the amount of time that has elapsed since
the previous message was written.

This change has the key consequence that if the callback function
is invoked one or more times with a negative value for its "total"
parameter, and is invoked a final time with matching non-negative
values for its "written" and "total" parameters, it will always
write a progress log message at that time.

When this change is combined with the revisions we have made to the
"callbackState" structure's doCallbackIfRequired() method in this
commit, the result is that if an object's total size is initially
unknown, when an EOF condition is encountered while reading the
object's data, then a final progress log message is guaranteed to
be written with the total size of the object represented as equal
to the actual number of bytes that were read.

To verify this new behaviour, we add or update a number of our tests,
starting with the TestCopyCallbackFileThrottle() test function in
our "lfs" package.  Most significantly, we update this function's
"initial total unknown" test case so that it now expects a final
log message in which the total size of the object is not negative
but matches the total number of bytes read.

Note that the first log message expected by our new "initial total
unknown" test case still contains a "-1" in the denominator of the
fraction representing the amount of source data read so far.  We will
refine this field in a subsequent commit in this PR so that negative
"total" parameter values are no longer reported in a literal manner.

We also add two new test cases for the TestCopyCallbackFileThrottle()
function, in order to simulate situations where the total size of
an object is initially either overestimated or underestimated.  In
both cases, a final callback should be made in which the "total"
parameter value has been adjusted to match the actual number of
bytes that have been read when the EOF condition is reached.

To simulate these additional test cases, we expand the setup() and
Assert() methods of the "copyCallbackFileThrottleTestCase" structure
we introduced to our "lfs/util_test.go" source file in a previous
commit in this PR.

For the particular test case where the total size of an object is
underestimated, the Assert() method now performs three extra calls to
the Read() method of the CallbackReader structure, with a simulated
delay between the first two of these calls.  The first of these calls
should never result in a log message being written, while the second
should produce a log message in which the number of bytes read so far
exceeds the total size of the object.  For both new test cases, when
the EOF condition is reached, a callback should be made which produces
a log message with the object's total size adjusted in the final log
message to match the actual number of bytes read.

To independently verify the new behaviour of the "callbackState"
structure's doCallbackIfRequired() method, we add a test function to
our "tools" package which also simulates situations in which the
total size of the object is either unknown, overestimated, or
underestimated.

The TestBothCallbackReadersInvokeCallbackOnEOFWhenTotalSizeIncorrect()
function confirms that the Read() methods of both the BodyWithCallback
and CallbackReader structures perform a final callback when the EOF
condition is reached and pass the callback function an updated value
for the total size of the object which matches the actual number of
bytes read.  Note that in a prior commit in this PR we refactored the
Read() methods of both of the BodyWithCallback and CallbackReader
structures so that these methods now just invoke the read() method of
a "callbackState" structure, which in turn executes the
doCallbackIfRequired() method, so we do not need to provide a test
of the doCallbackIfRequired() method itself.

In addition to these changed or new Go test functions, we also expand
our "t/t-progress.sh" shell script with two new tests, one of which
exercises the "git lfs smudge" command under the specific set of
conditions we described above.

Our new "progress log: unknown initial size (smudge)" shell test
forces the use of the "git lfs smudge" command by a "git clone"
command and specified a progress log file using the GIT_LFS_PROGRESS
environment variable.  As well, in the repository cloned by the
"git clone" command, the test establishes a Git LFS object with
the special key string "storage-download-encoding-gzip" as its
contents, which causes our "lfstest-gitserver" test utility program
to return the object's contents in an HTTP response with a
gzip-encoded body and without a Content-Length header.

The test then checks that the progress log file contains an entry
with the full size of the object reported in both the numerator and
denominator of the field which represents the amount of data
downloaded for the object.  Previously, all progress log entries
generated by the "git lfs smudge" command while downloading a
content-encoded object would have a "-1" in the field's denominator.

Note that any intermediate entries preceding the final log entry
will still have a negative value in this field, but we will address
that issue in a subsequent commit in this PR.

(Note also that we use the same "storage-download-encoding-gzip"
special object content key for a more complete test of the Git LFS
client's handling of gzip-encoded responses in the "batch storage
HTTP download with gzip encoding" test in our
"t/t-batch-storage-encoding.sh" shell script.)

The other new shell test in our "t/t-progress.sh" script is named
"progress log: unknown initial size (fetch/pull)", and operates in
a similar manner to the "progress log: unknown initial size (smudge)"
test except that it exercises the "git lfs fetch" and "git lfs pull"
commands rather than the "git lfs smudge" command.

As noted in the following comment on PR #6011, our "git lfs fetch"
and "git lfs pull" commands may write progress log entries with a "-1"
value in the denominator of the field which represents the amount of
data downloaded for the object, if the HTTP response to an object
download request is content-encoded and lacks a Content-Length header.

  #6011 (comment)

In these commands, a transfer queue is created using the
WithProgress() option function rather than the WithProgressCallback()
option function, so the "cb" field of the TransferQueue structure
from our "tq" package is nil.  However, both commands pass a Meter
structure from our "tq" package to the WithProgress() function,
so the TransferQueue structure's "m" field is non-nil.

As a result, when the TransferQueue structure's ensureAdapterBegun()
method is executed, the callback function it creates will execute
only the TransferBytes() method of the Meter structure, which in
turn does not immediately return without taking any action because
its "m" receiver parameter is non-nil.  By comparison, when the
WithProgressCallback() option function is used instead of the
WithProgress() option function, this same callback function runs
the TransferBytes() method, which returns immediately, and then
runs the callback function specified by the non-nil "cb" field.

The callback function created by the ensureAdapterBegun() method
is then passed to the Begin() method of the transfer adapter, and
ultimately passed to the CopyWithCallback() function of our "tools"
package by the "basicDownloadAdapter" structure's download() method.
(Note that this is also true for our "git lfs filter-process" and
"git lfs smudge" commands, not just for the "git lfs fetch"
and "git lfs pull" commands.)

As described above regarding the "git lfs smudge" command, the
CopyWithCallback() function initializes a new CallbackReader structure
and so the callback function passed to the CopyWithCallback() function
will ultimately be invoked as object data is read from the HTTP
response body.  With the "git lfs fetch" and "git lfs pull" commands,
though, this callback function only runs the TransferBytes() method
of the Meter structure, and that method does not return immediately
but runs the logBytes() method of the same structure.

For historical reasons which date back to the introduction of the
logBytes() method in commit 710862b
of PR #476, this method writes a line to the progress log file with
the identical format as the lines generated by the callback function
created by the CopyCallbackFile() method of the GitFilter structure.

However, unlike that anonymous callback function, the logBytes()
method does not limit its output based on the amount of time that
has elapsed since it was previously invoked.  When we revised the
CopyCallbackFile() method in PR #5504 to implement a mechanism
which throttled the frequency of its output to the progress log,
we did not also update the logBytes() method to do the same.

While we likely should refactor the logBytes() method and the
CopyCallbackFile() method's callback function to share a common
implementation, that change falls outside of the scope of this PR,
so we defer it to a future PR.

What this PR does accomplish, though, is to ensure that regardless
of their source, when progress log messages are written for an object
whose total size is initially unknown, a final callback will be made
after the EOF condition is encountered, and this will generate a
progress log message in which the total size has been adjusted to
match the actual number of bytes read.

For this reason, our "progress log: unknown initial size (fetch/pull)"
shell test exercises the "git lfs fetch" and "git lfs pull" commands
with a progress log file specified in the GIT_LFS_PROGRESS environment
variable and an HTTP object download response that lacks a
Content-Length header.  Like our other new shell test, this test
also uses the "storage-download-encoding-gzip" special object
content key to cause the "lfstest-gitserver" utility to gzip-encode
its response to an object download request.

The test then confirms that the progress logs generated by the
"git lfs fetch" and "git lfs pull" commands contain an entry with
the full size of the object reported in both the numerator and
denominator of the field which represents the amount of data
downloaded for the object.  Previously, all progress log entries
generated by these commands while downloading a content-encoded
object would have a "-1" in the field's denominator.

Note that any intermediate entries preceding the final log entry
will still have a negative value in this field, but we will address
that issue in a subsequent commit in this PR.
chrisd8088 added a commit that referenced this pull request Aug 5, 2026
As described in a previous commit in this PR, several of our Git LFS
commands may write progress log messages with a negative value in
the denominator of the fraction representing the amount of data
downloaded so far for an individual object.  Specifically, the
"git lfs fetch", "git lfs pull", and "git lfs smudge" commands
will write such log messages when a progress log is enabled with
the GIT_LFS_PROGRESS environment variable and the response to an
HTTP object download request is content-encoded and therefore lacks
a Content-Length header.

As described in a previous commit in this PR, for historical reasons
progress log messages are written either by the anonymous callback
function created by the CopyCallbackFile() method of the GitFilter
structure in our "lfs" package, or by the logBytes() method of the
Meter structure in our "tq" package.  However, the format of the
messages is identical regardless of which function or method
generates them.

When the logBytes() method was first introduced in commit
710862b of PR #476, it duplicated
the format of the progress log messages generated by the callback
function created by the CopyCallbackFile() method.  The current
progress log message format in that method dates from commit
36fa23d of PR #100, but the original
version of the method and its callback function themselves were added
in commit fd41906 of PR #97.

While we likely should refactor the logBytes() method and the
CopyCallbackFile() method's callback function to share a common
implementation, that change falls outside of the scope of this PR,
so we defer it to a future PR.

However, one of the changes we made in a prior commit in this PR
now ensures that if an object's total size is initially unknown,
when an EOF condition is encountered while reading the object's
data, then a final progress log message is guaranteed to be written
with the total size of the object represented as equal to the
actual number of bytes that were read.  Further, this final
progress log entry will be output regardless of whether the
CopyCallbackFile() method's callback function or the logBytes()
method is being used to write messages to the log file.

While this change affects the content of the last progress log
entry written for a given object, until the EOF condition is
reached, intermediate log messages may be generated which still
have a negative value in the denominator of the fraction
representing the amount of the object's data processed so far.

These negative values occur because the length of the data to be
read is initially unknown.  At present, the only circumstance in
which this is possible is when the HTTP response to an object
download request lacks a Content-Length header, as will be the
case when the response body is gzip-encoded, as we noted in the
following comment on PR #6011:

  #6011 (comment)

PR #6011 resolves a bug in our "git lfs filter-progress" and
"git lfs clean" commands whereby they can pass an incorrect
"totalSize" parameter to the CopyWithCallback() function.  The only
solution for this problem is for the commands to simply not attempt
to determine the total size of an object.  As a consequence, we
expect that our "git lfs filter-progress" and "git lfs clean" commands
will never know in advance the length of the object data they are
reading from Git, and it will become a more common occurrence for
the CopyCallbackFile() method's callback function and the logBytes()
method to receive a "total" parameter with a negative value.

We therefore now refine the format of the progress log when the
total size of an object is unknown by writing a series of question
mark characters ("?") in place of the denominator of the fraction
which represents the amount of the object's data processed so far.
We adjust the number of these question mark characters to match
the length of the numerator, e.g., "123/???" and "12345/?????".

To avoid implementing the necessary string formatting logic in
both the CopyCallbackFile() method's callback function and the
logBytes() method, we introduce a new FormatFraction() function
to our "tools" package and then substitute its output in place
of the appropriate fraction field in the log messages.

We then add a TestFormatFraction() Go test function which verifies
that the FormatFraction() function generates the expected output
under a range of conditions, including when the number of bytes
read so far exceeds the value provided as the total size of an
object, and when the total size of an object is unknown and should
be represented using various numbers of question mark characters.

Finally, we update the comments in several of the tests we added
to the "t/t-progress.sh" shell script in a prior commit of this PR,
and we revise the "initial total unknown" test case for our
TestCopyCallbackFileThrottle() test function.  In that test case,
we update the expected contents of the progress log because the
intermediate entry which precedes the final entry should now have
a series of question mark characters rather than a "-1" value in
the denominator of the fraction which represents the amount of the
object's data processed so far.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants