Changeset 3363

Show
Ignore:
Timestamp:
01/13/10 18:46:02 (10 years ago)
Author:
armon
Message:

Fixed double counting of time consumption by threads in Island stats. Re-wrote the handling of stop's inside an API call to consider all stops, and to be based on proportion of time spent, rather than strangeness based on difference between actual and expected time.

Files:
1 modified

Legend:

Unmodified
Added
Removed
  • seattle/trunk/cadet/island_stats.py

    r3343 r3363  
    371371              expected_time = max(over_use / use_limit, 0) 
    372372 
    373             # Determine the actual time spent 
    374             actual_time = after_stop_event[1] - before_stop_event[1] 
    375          
    376             # Determine the difference between the actual and expected time 
    377             diff_time = actual_time - expected_time 
    378  
    379             # NOTE: If the difference in actual vs. expected time is greater than 
    380             # the stoptime, attribute this the stopping. Otherwise, ignore the stop. 
     373            # Determine the actual time spent in the API 
     374            api_start = before_stop_event[1] 
     375            api_end = after_stop_event[1] 
     376            actual_time = api_end - api_start  
     377        
     378            # Determine the sum of all the stoptimes during this API call 
     379            all_stops = get_stoptimes_on_interval(api_start, api_end) 
     380            all_stoptimes = 0 
     381            for stop in all_stops: 
     382              TOS, stop_amount = stop 
     383              all_stoptimes += stop_amount 
     384 
     385 
     386            # NOTE: If the proportion of the stoptime to the actual time is greater than 
     387            # the proportion of the expected time, then attribute this the stopping.  
     388            # Otherwise, ignore the stop. 
    381389            # This is somewhat troublesome, since in some cases the diff_time may be great. 
    382390            # E.g. on a sock.recv() there may be no data available. So, the big actual_time is 
     
    384392            # will cause the "stopped" time to increase, but it is hard to blame anything since 
    385393            # that time is not caused by a limited netrecv anyways. 
    386             if diff_time > amount: 
    387               commit_time(thread_dict, TOC) 
    388               thread_dict["begin"] = resume_time 
    389               thread_dict["stopped"] += amount 
     394            if all_stoptimes > expected_time: 
     395              # If this is the first stop during this API, we will do all the 
     396              # accounting now 
     397              if all_stops[0][0] == TOC: 
     398                # The amount of time spent on the "resource" is at a minimum 
     399                # the expected time, or the actual_time - stopped_time 
     400                resource_time = max(expected_time, actual_time - all_stoptimes) 
     401 
     402                # Add the resource time 
     403                thread_dict[thread_dict["resource"]] += resource_time 
     404                thread_dict["begin"] = api_end 
     405         
     406                # Make sure everything adds up. If the resource_time is 
     407                # actual_time - stopped_time, then this is just adding the 
     408                # stopped time. Otherwise this is the actual_time - expected_time. 
     409                thread_dict["stopped"] += actual_time - resource_time 
    390410 
    391411          else: 
     
    483503  # Total all the threads 
    484504  for thread,thread_dict in thread_usages.items(): 
    485     if thread != ALL_THREADS: 
    486       for type in TIME_UTIL_KEYS: 
    487         total_time[type] += thread_dict[type] 
     505    if thread_dict is total_time: 
     506      continue 
     507    for type in TIME_UTIL_KEYS: 
     508      total_time[type] += thread_dict[type] 
    488509 
    489510 
     
    509530          if thread_time[type] > 0.0: 
    510531            print "  Total '"+type+"': " + str(thread_time[type]) + " (" + str(round(100 * thread_time[type] / thread_time["live"], 2)) + "%)" 
    511             total_time[type] += thread_time[type] 
    512532 
    513533  print "\nAll Threads (Global)"