Measuring response time in AFNetworking HTTP GET

Question

I am trying to measure time taken per GET request when downloading a file using AFNetworking. I am downloading a file repeatedly in a loop. The problem I am having is that the way I am measuring total time, it gives a much larger total time than it actually is. For example, for 50 downloads it gives 72 sec but in reality it only took around 5 sec. I also suspect 5 sec is too low for 50 downloads(the download size is 581 kb per file).

How do I effectively measure time in this case? I need time from the moment request is fired till response in received.

My method to download file:

- (void) HTTPGetRequest
{    
    startTime = CACurrentMediaTime(); // Start measuring time

    AFHTTPClient *httpClient = [[AFHTTPClient alloc] initWithBaseURL:http://myServer];
    NSMutableURLRequest *request = [httpClient requestWithMethod:@"GET"
                                                            path:@"/download/Text581KB.txt"
                                                      parameters:nil];
    AFHTTPRequestOperation *operation = [[AFHTTPRequestOperation alloc] initWithRequest:request];
    [httpClient registerHTTPOperationClass:[AFHTTPRequestOperation class]];

    // Save downloaded file
    NSArray *paths = NSSearchPathForDirectoriesInDomains(NSDocumentDirectory, NSUserDomainMask, YES);
    NSString *path = [[paths objectAtIndex:0] stringByAppendingPathComponent:[NSString stringWithFormat:@"Text581KB.txt"]];
    operation.outputStream = [NSOutputStream outputStreamToFileAtPath:path append:NO];

    [operation setCompletionBlockWithSuccess:^(AFHTTPRequestOperation *operation, id responseObject) {
        double elapsedTime = (CACurrentMediaTime() - startTime); // Measuring time
        totalTime += elapsedTime; // Measuring total time HERE!
        [results setString:[NSString stringWithFormat: @"Current Transaction Time: %f sec\nTotal Time: %f sec", elapsedTime, totalTime]];
        [_resultLabel performSelectorOnMainThread:@selector(setText:) withObject:results waitUntilDone:NO];
    } failure:^(AFHTTPRequestOperation *operation, NSError *error) {
        NSLog(@"Error: %@", error);
    }];

    [operation setDownloadProgressBlock:^(NSUInteger bytesWritten, long long totalBytesWritten, long long totalBytesExpectedToWrite) {  ((int)totalBytesExpectedToWrite));
        totalDownloadSize += totalBytesExpectedToWrite;
        [_DataTransferredLabel setText:[NSString stringWithFormat:@"Total Download Size: %@", [self getFileSize:totalDownloadSize/1024]]];
    }];

    [operation setCacheResponseBlock:^NSCachedURLResponse *(NSURLConnection *connection, NSCachedURLResponse *cachedResponse) {
        return nil;
    }];
    [operationQueue addOperation:operation];
}

I am creating a NSOperationQueue in my viewDidLoad:

operationQueue = [NSOperationQueue new];
[operationQueue setMaxConcurrentOperationCount:1]; // using this as I was suspecting downloads were happening in parallel & thus 50 downloads finishing in a few secs

I am invoking the HTTPGetRequest method as follows:

- (IBAction)startDownload:(UIButton *)sender {
    totalCount = [[_countText text] longLongValue]; // get # of times to download
    long currentCount = 1;
    completedCount = 0;
    totalTime = 0;
    totalDownloadSize = 0;
    while (currentCount <= totalCount)
    {
        [self HTTPGetRequest];
        [results setString:@""];
        currentCount++;

    }

Answer 1

Use AFHTTPRequestOperationLogger.

Answer 2

Another option is to inject the "fire" date in the operation's userInfo by observing the AFNetworkingOperationDidStartNotification notification.

//AFHTTPRequestOperation *operation = [...]
id __block observer = [[NSNotificationCenter defaultCenter] addObserverForName:AFNetworkingOperationDidStartNotification
        object:operation
         queue:nil
    usingBlock:^(NSNotification *note) {
                   operation.userInfo = @{@"fireDate": [NSDate date]};
                   [[NSNotificationCenter defaultCenter] removeObserver:observer];
              }];

Answer 3

In terms of calculating cumulative time (not elapsed time), I have just created a subclass of AFHTTPRequestOperation that captures the start time. Otherwise, you won't know precisely when it started:

@interface TimedAFHTTPRequestOperation : AFHTTPRequestOperation

@property (nonatomic) CFAbsoluteTime startTime;

@end

@implementation TimedAFHTTPRequestOperation

- (void)start
{
    self.startTime = CFAbsoluteTimeGetCurrent();

    [super start];
}

@end

(Note I'm using CFAbsoluteTimeGetCurrent versus CACurrentMediaTime; use whatever you want, but just be consistent.)

Then in the code that's doing the downloads, you can use this TimedAFHTTPRequestOperation instead of AFHTTPRequestOperation:

TimedAFHTTPRequestOperation *operation = [[TimedAFHTTPRequestOperation alloc] initWithRequest:request];

That code's completion block can then use the startTime property of TimedAFHTTPRequestOperation to calculate the time elapsed for the given operation and add it to the total time:

[operation setCompletionBlockWithSuccess:^(AFHTTPRequestOperation *operation, id responseObject) {
    TimedAFHTTPRequestOperation *timedOperation = (id)operation;
    CFTimeInterval elapsedTime = CFAbsoluteTimeGetCurrent() - timedOperation.startTime;
    self.totalTime += elapsedTime; // Measuring total time HERE!
    NSLog(@"finished in %.1f", elapsedTime);
} failure:^(AFHTTPRequestOperation *operation, NSError *error) {
    NSLog(@"Error: %@", error);
}];

That's how you calculate the elapsedTime and append them together to calculate the totalTime.

In terms of how to know when the operations are done, I would

• modify HTTPGetRequest to return a NSOperation;

• have startDownload create a completion operation and then add all of these operations as dependencies:

  NSOperation *completionOperation = [NSBlockOperation blockOperationWithBlock:^{
      NSLog(@"finished all in cumulative time: %.1f", self.totalTime);
  }];
  
  for (NSInteger i = 0; i < totalCount; i++)
  {
      NSOperation *operation = [self HTTPGetRequest];
      [completionOperation addDependency:operation];
  }
  [self.operationQueue addOperation:completionOperation];
  

That achieves several goals, namely creating a completion operation, calculating the total time (as opposed to the total time elapsed).

By the way, I'd also suggest pulling the creation of AFHTTPClient out of your HTTPGetRequest. You should probably only create one per app. This is especially important in case you ever started using enqueueHTTPRequestOperation instead of creating your own operation queue. I also see no need for your call to registerHTTPOperationClass.

---

You are incrementing the totalElapsed by elapsedTime, but elapsedTime is calculated from startTime, which itself represents the time that the jobs were first queued, not when the download actually started. Remember that HTTPGetRequest returns almost immediately (having set elapsedTime). Thus if you're queueing five downloads, I wouldn't be surprised that HTTPGetRequest runs five times (and sets and resets startTime five times) before the first request even is initiated.

The question is further complicated by the question of whether you're doing concurrent downloads, and if so, what you then mean by "total elapsed". Let's say you have two concurrent downloads, one that takes 5 seconds, another takes 7 seconds. Do you want the answer to be 7 (because they both finished in 7 seconds)? Or do you want the answer to be 12 (because they both finished in a cumulative 12 seconds)?

I'm presuming that you're looking for, in this scenario, 7 seconds, then you should set the startTime once before you initiate all of your requests, and then only calculate when all of the downloads are done. You could, for example, rather than doing any calculations in HTTPGetRequest at all, just add your own operation that is dependent upon all the other operations you added, which calculates the total elapsed. at the very end. Or, if you want the the total elapsed to just reflect the total elapsed while you're in the process of downloading, then just set totalElapsed rather than incrementing it.