227603 - performance - history still slow

Reporter

Description

•

21 years ago

I'm running a modified history manager that flattens out the per-day listings
into a single flat (sorted by date) list per day. The performance of the Gecko
side is still very slow. I instrumented my code and here are some numbers:

2003-12-05 17:36:23.994 Camino[6783] Building grandChildNodes list for name=0
2003-12-05 17:36:24.619 Camino[6783] Cache build time 619.193435 ms, 15.479836
ms per child, 40 children
2003-12-05 17:36:33.348 Camino[6783] Building grandChildNodes list for name=1
2003-12-05 17:36:34.737 Camino[6783] Cache build time 1388.851047 ms, 19.289598
ms per child, 72 children
2003-12-05 17:36:43.113 Camino[6783] Building grandChildNodes list for name=2
2003-12-05 17:36:43.514 Camino[6783] Cache build time 400.627181 ms, 15.408738
ms per child, 26 children
2003-12-05 17:36:46.500 Camino[6783] Building grandChildNodes list for name=3
2003-12-05 17:36:48.537 Camino[6783] Cache build time 2037.043959 ms, 18.026938
ms per child, 113 children
2003-12-05 17:36:51.992 Camino[6783] Building grandChildNodes list for name=4
2003-12-05 17:36:52.454 Camino[6783] Cache build time 460.868984 ms, 16.459607
ms per child, 28 children
2003-12-05 17:36:54.230 Camino[6783] Building grandChildNodes list for name=5
2003-12-05 17:36:54.687 Camino[6783] Cache build time 457.187206 ms, 15.765076
ms per child, 29 children

Here's the instrumented code:

- (void)buildGrandChildCache;
{
  if( !kFlattenHistory )
    return;
  if( ![self shouldUseGrandChildNodes] )
    return;
  NSLog(@"Building grandChildNodes list for name=%@", [self name]);
  NSMutableArray * grandChildNodes = [[NSMutableArray alloc] init];
  int childCount = [mChildNodes count];
  NSDate * inspectStartDate = [NSDate dateWithTimeIntervalSinceNow:0.0];
  for( int i=0; i < childCount; i++ ) {
    HistoryItem * curChild = [mChildNodes objectAtIndex:i];
    int grandChildCount = [curChild nativeNumChildren];
    for( int j=0; j < grandChildCount; j++ ) {
      HistoryItem * curGrandChild = [curChild nativeChildAtIndex:j];
      [grandChildNodes addObject:curGrandChild];
    }
  }
  NSDate * inspectStopDate = [NSDate dateWithTimeIntervalSinceNow:0.0];
  double inspectElapsedTime = [inspectStopDate
timeIntervalSinceDate:inspectStartDate];
  double inspectTimePer = inspectElapsedTime / childCount;
  NSLog(@"Cache build time %f ms, %f ms per child, %i
children",inspectElapsedTime*1000,inspectTimePer*1000, childCount);
  NSArray * sorted = [grandChildNodes
sortedArrayUsingSelector:@selector(historyItemDateCompare:)];
  mGrandChildNodes = [sorted retain];
}

S Woodside

Reporter

Comment 1

•

21 years ago

This is truly odd.

2003-12-05 18:15:05.797 Camino[7654] Building grandChildNodes list for name=Today
2003-12-05 18:15:05.797 Camino[7654] HasMoreElements time 0.052109 ms
self=<HistoryItem: 0x5a9dcb0>
2003-12-05 18:15:05.806 Camino[7654] HasMoreElements time 0.059828 ms
self=<HistoryItem: 0x5a9dd30>
2003-12-05 18:15:05.814 Camino[7654] HasMoreElements time 0.077367 ms
self=<HistoryItem: 0x5a9deb0>
2003-12-05 18:15:05.822 Camino[7654] HasMoreElements time 0.089705 ms
self=<HistoryItem: 0x5a9e020>
2003-12-05 18:15:05.830 Camino[7654] HasMoreElements time 0.102177 ms
self=<HistoryItem: 0x5a9e880>
2003-12-05 18:15:05.839 Camino[7654] HasMoreElements time 0.965446 ms
self=<HistoryItem: 0x5a9e950>
2003-12-05 18:15:05.847 Camino[7654] HasMoreElements time 1.083180 ms
self=<HistoryItem: 0x5a9eac0>
2003-12-05 18:15:05.855 Camino[7654] HasMoreElements time 1.169354 ms
self=<HistoryItem: 0x5a9ebf0>
2003-12-05 18:15:05.865 Camino[7654] HasMoreElements time 1.152992 ms
self=<HistoryItem: 0x5a9ee70>
2003-12-05 18:15:05.873 Camino[7654] HasMoreElements time 1.252785 ms
self=<HistoryItem: 0x5a9eef0>
2003-12-05 18:15:05.882 Camino[7654] HasMoreElements time 1.403585 ms
self=<HistoryItem: 0x5a9f070>
2003-12-05 18:15:05.890 Camino[7654] HasMoreElements time 1.773328 ms
self=<HistoryItem: 0x5a9f1e0>
2003-12-05 18:15:05.908 Camino[7654] HasMoreElements time 2.623677 ms
self=<HistoryItem: 0x5a9e3c0>
2003-12-05 18:15:05.916 Camino[7654] HasMoreElements time 2.832487 ms
self=<HistoryItem: 0x5a9f5f0>
2003-12-05 18:15:05.925 Camino[7654] HasMoreElements time 2.754837 ms
self=<HistoryItem: 0x5a9f6e0>
2003-12-05 18:15:05.933 Camino[7654] HasMoreElements time 2.795219 ms
self=<HistoryItem: 0x5a9f8e0>
2003-12-05 18:15:05.945 Camino[7654] HasMoreElements time 6.310344 ms
self=<HistoryItem: 0x5a9f990>
2003-12-05 18:15:05.953 Camino[7654] HasMoreElements time 6.395802 ms
self=<HistoryItem: 0x5a9fb70>
2003-12-05 18:15:05.961 Camino[7654] HasMoreElements time 6.753862 ms
self=<HistoryItem: 0x5a9fc80>
2003-12-05 18:15:05.969 Camino[7654] HasMoreElements time 7.308245 ms
self=<HistoryItem: 0x5a9c710>
2003-12-05 18:15:05.977 Camino[7654] HasMoreElements time 6.788328 ms
self=<HistoryItem: 0x5a9c7c0>
2003-12-05 18:15:05.985 Camino[7654] HasMoreElements time 6.676421 ms
self=<HistoryItem: 0x5a9c9e0>
2003-12-05 18:15:05.993 Camino[7654] HasMoreElements time 6.910905 ms
self=<HistoryItem: 0x5a9ca90>
2003-12-05 18:15:06.061 Camino[7654] HasMoreElements time 66.777408 ms
self=<HistoryItem: 0x5a9cc20>
2003-12-05 18:15:06.079 Camino[7654] HasMoreElements time 7.228851 ms
self=<HistoryItem: 0x5a9f310>
2003-12-05 18:15:06.093 Camino[7654] HasMoreElements time 7.027686 ms
self=<HistoryItem: 0x5a9cd70>
2003-12-05 18:15:06.122 Camino[7654] HasMoreElements time 27.942300 ms
self=<HistoryItem: 0x5a9cf70>
2003-12-05 18:15:06.143 Camino[7654] HasMoreElements time 7.274702 ms
self=<HistoryItem: 0x5aa07b0>
2003-12-05 18:15:06.164 Camino[7654] HasMoreElements time 7.262066 ms
self=<HistoryItem: 0x5aa09b0>
2003-12-05 18:15:06.189 Camino[7654] HasMoreElements time 10.663792 ms
self=<HistoryItem: 0x5aa0aa0>
2003-12-05 18:15:06.204 Camino[7654] HasMoreElements time 7.218271 ms
self=<HistoryItem: 0x5aa0bd0>
2003-12-05 18:15:06.212 Camino[7654] HasMoreElements time 7.084623 ms
self=<HistoryItem: 0x5aa0d60>
2003-12-05 18:15:06.221 Camino[7654] HasMoreElements time 7.399991 ms
self=<HistoryItem: 0x5a9fad0>
2003-12-05 18:15:06.238 Camino[7654] HasMoreElements time 16.943425 ms
self=<HistoryItem: 0x5aa10d0>
2003-12-05 18:15:06.247 Camino[7654] HasMoreElements time 7.677004 ms
self=<HistoryItem: 0x5a8a5a0>
2003-12-05 18:15:06.255 Camino[7654] HasMoreElements time 7.216290 ms
self=<HistoryItem: 0x5a8a720>
2003-12-05 18:15:06.264 Camino[7654] HasMoreElements time 8.112967 ms
self=<HistoryItem: 0x5a8a890>
2003-12-05 18:15:06.272 Camino[7654] HasMoreElements time 7.630035 ms
self=<HistoryItem: 0x5a8aa90>
2003-12-05 18:15:06.307 Camino[7654] HasMoreElements time 33.512443 ms
self=<HistoryItem: 0x5a8ab80>
2003-12-05 18:15:06.319 Camino[7654] Cache build time 521.906927 ms, 13.047673
ms per child, 40 children


Here's the code. Did I make a mistake?

- (void)buildChildCache;
{
  NSMutableArray * childNodes = [[[NSMutableArray alloc] init] retain];
  
  [self invalidateCache];

  nsCOMPtr<nsIRDFResource> childRDFProperty;
   
mRDFService->GetResource(nsDependentCString("http://home.netscape.com/NC-rdf#child"),
                           getter_AddRefs(childRDFProperty));
  nsCOMPtr<nsISimpleEnumerator> childNodesEnum;
  mRDFDataSource->GetTargets(mRDFResource, childRDFProperty, PR_TRUE,
getter_AddRefs(childNodesEnum));
  
  NSDate * inspectStartDate = [NSDate dateWithTimeIntervalSinceNow:0.0];
  bool inspectTimeIt = YES;
  PRBool hasMore = PR_FALSE;
  while( NS_SUCCEEDED(childNodesEnum->HasMoreElements(&hasMore)) && hasMore ) {
    if( inspectTimeIt ) {
      NSDate * inspectStopDate = [NSDate dateWithTimeIntervalSinceNow:0.0];
      double inspectElapsedTime = [inspectStopDate
timeIntervalSinceDate:inspectStartDate];
      NSLog(@"HasMoreElements time %f ms self=%@", inspectElapsedTime*1000, self);
      inspectTimeIt = NO;
    }
    nsCOMPtr<nsISupports> supp;
    childNodesEnum->GetNext(getter_AddRefs(supp));
    nsCOMPtr<nsIRDFResource> childResource = do_QueryInterface(supp);
    if (childResource) {
      RDFItem * childItem = [self newChildWithRDFResource:childResource
RDFDataSource:mRDFDataSource];
      if (childItem)
        [childNodes addObject:childItem];
    }
  }
  mChildNodes = [childNodes retain];
}

S Woodside

Reporter

Comment 2

•

21 years ago

More times. This time I measured the performance of just the
childNodesEnum->HasMoreElements call alone as it loopst hrough the enumerator.
Notice how erratic the times "per call" are between different invokations (on
invocation per site folder). Summary, and then the instrumented code below.

Building grandChildNodes list for name=Today
HasMoreElements time  36.77 ms,  4.60 ms per call,   8 calls
HasMoreElements time  14.04 ms,  4.68 ms per call,   3 calls
HasMoreElements time   0.08 ms,  0.08 ms per call,   1 calls
HasMoreElements time   0.09 ms,  0.09 ms per call,   1 calls
HasMoreElements time   0.10 ms,  0.10 ms per call,   1 calls
HasMoreElements time   1.04 ms,  1.04 ms per call,   1 calls
HasMoreElements time   8.47 ms,  4.24 ms per call,   2 calls
HasMoreElements time  40.86 ms,  4.09 ms per call,  10 calls
HasMoreElements time   1.12 ms,  1.12 ms per call,   1 calls
HasMoreElements time   8.27 ms,  4.14 ms per call,   2 calls
HasMoreElements time   1.38 ms,  1.38 ms per call,   1 calls
HasMoreElements time  56.09 ms,  7.01 ms per call,   8 calls
HasMoreElements time   2.44 ms,  2.44 ms per call,   1 calls
HasMoreElements time  12.48 ms, 12.48 ms per call,   1 calls
HasMoreElements time  11.11 ms,  5.56 ms per call,   2 calls
HasMoreElements time   2.67 ms,  2.67 ms per call,   1 calls
HasMoreElements time  27.63 ms,  6.91 ms per call,   4 calls
HasMoreElements time   6.61 ms,  6.61 ms per call,   1 calls
HasMoreElements time   6.59 ms,  6.59 ms per call,   1 calls
HasMoreElements time  28.51 ms,  7.13 ms per call,   4 calls
HasMoreElements time  10.43 ms, 10.43 ms per call,   1 calls
HasMoreElements time   6.98 ms,  6.98 ms per call,   1 calls
HasMoreElements time   6.69 ms,  6.69 ms per call,   1 calls
HasMoreElements time   7.60 ms,  7.60 ms per call,   1 calls
HasMoreElements time   6.82 ms,  6.82 ms per call,   1 calls
HasMoreElements time   7.12 ms,  7.12 ms per call,   1 calls
HasMoreElements time  72.09 ms, 72.09 ms per call,   1 calls
HasMoreElements time  32.85 ms,  8.21 ms per call,   4 calls
HasMoreElements time  38.28 ms,  7.66 ms per call,   5 calls
HasMoreElements time  14.33 ms,  7.17 ms per call,   2 calls
HasMoreElements time   6.95 ms,  6.95 ms per call,   1 calls
HasMoreElements time  14.51 ms,  7.26 ms per call,   2 calls
HasMoreElements time  14.59 ms,  7.30 ms per call,   2 calls
HasMoreElements time  21.92 ms,  7.31 ms per call,   3 calls
HasMoreElements time  21.49 ms,  7.16 ms per call,   3 calls
HasMoreElements time   7.11 ms,  7.11 ms per call,   1 calls
HasMoreElements time   7.33 ms,  7.33 ms per call,   1 calls
HasMoreElements time 389.90 ms, 55.70 ms per call,   7 calls
HasMoreElements time  24.12 ms,  8.04 ms per call,   3 calls
Cache build time 445.785701 ms, 4.643601 ms per grandchild, 96 grandchildren


- (void)buildChildCache;
{
  NSMutableArray * childNodes = [[[NSMutableArray alloc] init] retain];
  
  [self invalidateCache];

  nsCOMPtr<nsIRDFResource> childRDFProperty;
   
mRDFService->GetResource(nsDependentCString("http://home.netscape.com/NC-rdf#child"),
                           getter_AddRefs(childRDFProperty));
  nsCOMPtr<nsISimpleEnumerator> childNodesEnum;
  mRDFDataSource->GetTargets(mRDFResource, childRDFProperty, PR_TRUE,
getter_AddRefs(childNodesEnum));

  double inspectElapsedTime = 0.0;
  bool inspectTimeIt = YES;
  NSDate * inspectStartDate = [NSDate dateWithTimeIntervalSinceNow:0.0];
  PRBool hasMore = PR_FALSE;
  while( NS_SUCCEEDED(childNodesEnum->HasMoreElements(&hasMore)) && hasMore ) {
    if( inspectTimeIt ) {
      NSDate * inspectStopDate = [NSDate dateWithTimeIntervalSinceNow:0.0];
      inspectElapsedTime += [inspectStopDate
timeIntervalSinceDate:inspectStartDate];

    }
    nsCOMPtr<nsISupports> supp;
    childNodesEnum->GetNext(getter_AddRefs(supp));
    nsCOMPtr<nsIRDFResource> childResource = do_QueryInterface(supp);
    if (childResource) {
      RDFItem * childItem = [self newChildWithRDFResource:childResource
RDFDataSource:mRDFDataSource];
      if (childItem)
        [childNodes addObject:childItem];
    }
  }
  int numChilds = [childNodes count];
  NSLog(@"HasMoreElements time %6.2f ms, %5.2f ms per call, %3i calls",
inspectElapsedTime*1000, inspectElapsedTime*1000/numChilds, numChilds);
  mChildNodes = [childNodes retain];
}

S Woodside

Reporter

Comment 3

•

21 years ago

that's a different of a THOUSAND times slower or faster between the minimum and
maximum avg. times for calls to nsISimpleEnumerator::HasMoreElements !!!!!!!

Mike Pinkerton (not reading bugmail)

Comment 4

•

21 years ago

cc'ing smfr, he might have a better idea on how you're doing your time sampling.

Simon Fraser [no longer active]

Assignee

Comment 5

•

21 years ago

Run Sampler/ThreadViewer, and that'll tell you why RDF is sucking.

Ludovic Hirlimann [:Usul]

Updated

•

21 years ago

Keywords: perf

S Woodside

Reporter

Comment 6

•

21 years ago

Thanks Simon, I tried ThreadViewer. I see that it spends a lot of time in
HasMoreElements (
http://lxr.mozilla.org/mozilla/source/xpfe/components/history/src/nsGlobalHistory.cpp#440
) which I notice, each time it's called, it runs a loop.

The next level above that is mainly NextRow and IsResult. I'll see if I can
figure out whether those two calls are slow, or if they're just being called a
lot in that loop.

Actually looking at HasMoreElements it only moves forwards once through the list
I think. So maybe the problem is in IsResult. Then we hit
matchAgeInDaysCallback. This presumably is needed because we are specifying to
get result just for a certain day. (
http://lxr.mozilla.org/mozilla/source/xpfe/components/history/src/nsGlobalHistory.cpp#320
)

Mike Pinkerton (not reading bugmail)

Updated

•

21 years ago

Target Milestone: --- → Camino1.0

Simon Fraser [no longer active]

Assignee

Comment 7

•

20 years ago

Mine.

Assignee: pinkerton → sfraser_bugs

Simon Fraser [no longer active]

Assignee

Comment 8

•

20 years ago

I ripped out RDF (bug 276733). It's fast now.

Status: NEW → RESOLVED

Closed: 20 years ago

Resolution: --- → FIXED

Bugzilla

Quick Search

performance - history still slow

Categories

(Camino Graveyard :: History, defect)

Tracking

(Not tracked)

People

(Reporter: sbwoodside, Assigned: sfraser_bugs)

References

Details

(Keywords: perf)

Crash Data

Security

(public)

User Story

Description

Comment 1

Comment 2

Comment 3

Comment 4

Comment 5

Updated

Comment 6

Updated

Comment 7

Comment 8