def test_history_performance(): try: tracemalloc.start() except: pass for _ in range( 3 ): path = "/tmp/test_performance_%d" % random.randint( 100000, 999999 ) if os.path.exists( path ): continue assert not os.path.exists( path ), "Couldn't find an unused name: %s" % path files = [] try: day = 24*60*60 dur = 3*day # a few days worth of data regstps = 0.0,5.0 # 0-5secs between updates numfiles = dur//day+1 # ~1 file/day, but at least 2 values = {} # Initial register values regscount = 1000 # Number of different registers regschanged = 1,10 # From 1-25 registers per row regsbase = 40001 start = timer() now = beg = start - dur linecnt = 0 for e in reversed( range( numfiles )): f = path + (( '.%d' % e ) if e else '') # 0'th file has no extension files.append( f ) with logger( f ) as l: if values: l.write( values, now=now ); linecnt += 1 while now < beg + len(files) * dur/numfiles: lst = now now += random.uniform( *regstps ) assert now >= lst assert timestamp( now ) >= timestamp( lst ), "now: %s, timestamp(now): %s" % ( now, timestamp( now )) updates = {} for _ in range( random.randint( *regschanged )): updates[random.randint( regsbase, regsbase + regscount - 1 )] = random.randint( 0, 1<<16 - 1 ) values.update( updates ) l.write( updates, now=now ); linecnt += 1 lst = now now += random.uniform( *regstps ) assert now >= lst assert timestamp( now ) >= timestamp( lst ) if e: # Compress .1 onward using a random format; randomly delete origin uncompressed file # so sometimes both files exist if random.choice( (True, False, False, False) ): continue # Don't make a compressed version of some files fz = f + '.%s' % random.choice( ('gz', 'bz2', 'xz') ) files.append( fz ) with opener( fz, mode='wb' ) as fd: with open( f, 'rb' ) as rd: fd.write( rd.read() ) if random.choice( (True, False, False) ): continue # Don't remove some of the uncompressed files os.unlink( f ) files.pop( files.index( f )) logging.warning( "Generated data in %.3fs; lines: %d", timer() - start, linecnt ) # Start somewhere within 0-1% the dur of the beg, forcing the load the look back to # find the first file. Try to do it all in the next 'playback' second (just to push it to # the max), in 'chunks' pieces. historical = timestamp( random.uniform( beg + dur*0/100, beg + dur*1/100 )) basis = timer() playback = 2.0 * dur/day # Can sustain ~2 seconds / day of history on a single CPU chunks = 1000 factor = dur / playback lookahead = 60.0 duration = None if random.choice( (True,False) ): duration = random.uniform( dur * 98/100, dur * 102/100 ) begoff = historical.value - beg endoff = 0 if duration is None else (( historical.value + duration ) - ( beg + dur )) logging.warning( "Playback starts at beginning %s %s, duration %s, ends at ending %s %s", timestamp( beg ), format_offset( begoff, ms=False ), None if duration is None else format_offset( duration, ms=False, symbols='-+' ), timestamp( beg + dur ), format_offset( endoff, ms=False )) ld = loader( path, historical=historical, basis=basis, factor=factor, lookahead=lookahead, duration=duration ) eventcnt = 0 slept = 0 cur = None while ld: once = False while ld.state < ld.AWAITING or not once: once = True upcoming = None limit = random.randint( 0, 250 ) if random.choice( (True,False) ): upcoming = ld.advance() if random.choice( (True,False) ) and cur: # ~25% of the time, provide an 'upcoming' timestamp that is between the # current advancing historical time and the last load time. upcoming-= random.uniform( 0, upcoming.value - cur.value ) cur,events = ld.load( upcoming=upcoming, limit=limit ) eventcnt += len( events ) advance = ld.advance() offset = advance.value - cur.value logging.detail( "%s loaded up to %s (%s w/ upcoming %14s); %4d future, %4d values: %4d events / %4d limit" , ld, cur, format_offset( offset ), format_offset( upcoming.value - advance.value ) if upcoming is not None else None, len( ld.future ), len( ld.values ), len( events ), limit ) logging.warning( "%s loaded up to %s; %3d future, %4d values: %6d events total", ld, cur, len( ld.future ), len( ld.values ), eventcnt ) try: snapshot = tracemalloc.take_snapshot() display_top( snapshot, limit=10 ) except: pass time.sleep( playback/chunks ) slept += playback/chunks elapsed = timer() - basis eventtps = eventcnt // ( elapsed - slept ) logging.error( "Playback in %.3fs (slept %.3fs); events: %d ==> %d historical records/sec", elapsed, slept, eventcnt, eventtps ) if not logging.getLogger().isEnabledFor( logging.NORMAL ): # Ludicrously low threshold, to pass tests on very slow machines assert eventtps >= 1000, \ "Historical event processing performance low: %d records/sec" % eventtps try: display_biggest_traceback() except: pass except Exception as exc: logging.normal( "Test failed: %s", exc ) ''' for f in files: logging.normal( "%s:\n %s", f, " ".join( l for l in open( f ))) ''' raise finally: for f in files: logging.detail( "unlinking %s", f ) try: os.unlink( f ) except: pass
def test_history_performance(): try: tracemalloc.start() except: pass for _ in range( 3 ): path = "/tmp/test_performance_%d" % random.randint( 100000, 999999 ) if os.path.exists( path ): continue assert not os.path.exists( path ), "Couldn't find an unused name: %s" % path files = [] try: day = 24*60*60 dur = 3*day # a few days worth of data regstps = 0.0,5.0 # 0-5secs between updates numfiles = dur//day+1 # ~1 file/day, but at least 2 values = {} # Initial register values regscount = 1000 # Number of different registers regschanged = 1,10 # From 1-25 registers per row regsbase = 40001 start = timer() now = beg = start - dur linecnt = 0 for e in reversed( range( numfiles )): f = path + (( '.%d' % e ) if e else '') # 0'th file has no extension files.append( f ) with logger( f ) as l: if values: l.write( values, now=now ); linecnt += 1 while now < beg + len(files) * dur/numfiles: lst = now now += random.uniform( *regstps ) assert now >= lst assert timestamp( now ) >= timestamp( lst ), "now: %s, timestamp(now): %s" % ( now, timestamp( now )) updates = {} for _ in range( random.randint( *regschanged )): updates[random.randint( regsbase, regsbase + regscount - 1 )] = random.randint( 0, 1<<16 - 1 ) values.update( updates ) l.write( updates, now=now ); linecnt += 1 lst = now now += random.uniform( *regstps ) assert now >= lst assert timestamp( now ) >= timestamp( lst ) if e: # Compress .1 onward using a random format; randomly delete origin uncompressed file # so sometimes both files exist if random.choice( (True, False, False, False) ): continue # Don't make a compressed version of some files fz = f + '.%s' % random.choice( ('gz', 'bz2', 'xz') ) files.append( fz ) with opener( fz, mode='wb' ) as fd: fd.write( open( f, 'rb' ).read() ) if random.choice( (True, False, False) ): continue # Don't remove some of the uncompressed files os.unlink( f ) files.pop( files.index( f )) logging.warning( "Generated data in %.3fs; lines: %d", timer() - start, linecnt ) # Start somewhere within 0-1% the dur of the beg, forcing the load the look back to # find the first file. Try to do it all in the next 'playback' second (just to push it to # the max), in 'chunks' pieces. historical = timestamp( random.uniform( beg + dur*0/100, beg + dur*1/100 )) basis = timer() playback = 2.0 * dur/day # Can sustain ~2 seconds / day of history on a single CPU chunks = 1000 factor = dur / playback lookahead = 60.0 duration = None if random.choice( (True,False) ): duration = random.uniform( dur * 98/100, dur * 102/100 ) begoff = historical.value - beg endoff = 0 if duration is None else (( historical.value + duration ) - ( beg + dur )) logging.warning( "Playback starts at beginning %s %s, duration %s, ends at ending %s %s", timestamp( beg ), format_offset( begoff, ms=False ), None if duration is None else format_offset( duration, ms=False, symbols='-+' ), timestamp( beg + dur ), format_offset( endoff, ms=False )) ld = loader( path, historical=historical, basis=basis, factor=factor, lookahead=lookahead, duration=duration ) eventcnt = 0 slept = 0 cur = None while ld: once = False while ld.state < ld.AWAITING or not once: once = True upcoming = None limit = random.randint( 0, 250 ) if random.choice( (True,False) ): upcoming = ld.advance() if random.choice( (True,False) ) and cur: # ~25% of the time, provide an 'upcoming' timestamp that is between the # current advancing historical time and the last load time. upcoming-= random.uniform( 0, upcoming.value - cur.value ) cur,events = ld.load( upcoming=upcoming, limit=limit ) eventcnt += len( events ) advance = ld.advance() offset = advance.value - cur.value logging.detail( "%s loaded up to %s (%s w/ upcoming %14s); %4d future, %4d values: %4d events / %4d limit" , ld, cur, format_offset( offset ), format_offset( upcoming.value - advance.value ) if upcoming is not None else None, len( ld.future ), len( ld.values ), len( events ), limit ) logging.warning( "%s loaded up to %s; %3d future, %4d values: %6d events total", ld, cur, len( ld.future ), len( ld.values ), eventcnt ) try: snapshot = tracemalloc.take_snapshot() display_top( snapshot, limit=10 ) except: pass time.sleep( playback/chunks ) slept += playback/chunks elapsed = timer() - basis eventtps = eventcnt // ( elapsed - slept ) logging.error( "Playback in %.3fs (slept %.3fs); events: %d ==> %d historical records/sec", elapsed, slept, eventcnt, eventtps ) if not logging.getLogger().isEnabledFor( logging.NORMAL ): # Ludicrously low threshold, to pass tests on very slow machines assert eventtps >= 1000, \ "Historical event processing performance low: %d records/sec" % eventtps try: display_biggest_traceback() except: pass except Exception as exc: logging.normal( "Test failed: %s", exc ) ''' for f in files: logging.normal( "%s:\n %s", f, " ".join( l for l in open( f ))) ''' raise finally: for f in files: logging.detail( "unlinking %s", f ) try: os.unlink( f ) except: pass
def test_history_unparsable(): """Test history files rendered unparsable due to dropouts. This should be handled with no problem except if the initial frame of register data on the first file is missing. """ for _ in range( 3 ): path = "/tmp/test_unparsable_%d" % random.randint( 100000, 999999 ) if os.path.exists( path ): continue assert not os.path.exists( path ), "Couldn't find an unused name: %s" % path files = [] try: # Create a series of history files with decreasing timestamps as the numeric extension # increases, containing records that are invalid. now = timer() v = 10000 secs = 10 secs_ext = 1.0 # adjust range of history to target out by this +/- basisext = .5 # adjust start basis time from now by this +/- minfactor = .25 maxfactor = 2.0 maxlatency = .25 # 1/N file lines corrupted (kills 2 records; the current and following). 0 --> no errors maxerror = random.choice( [ None, 3, 10, 100 ] ) oldest = None newest = None logging.normal( "Corrupting %s of all history lines", None if not maxerror else "1/%d" % maxerror ) for e in range( secs ): f = path + (( '.%d' % e ) if e else '') # 0'th file has no extension files.append( f ) with logger( f ) as l: ssend = 100 for ss in range( 0, ssend ): # subseconds up to but not including ssend... js = json.dumps( { 40001: v + e * 1000 + (ss * 1000 // ssend) } ) + '\n' if maxerror and not random.randint( 0, maxerror ): # Truncate some of the records (as would occur in a filesystem full or halt) js = js[:random.randint( 0, len( js ) - 1)] ts = timestamp( now - e + ss/ssend ) if oldest is None or ts < oldest: oldest = ts if newest is None or ts > newest: newest = ts l._append( '\t'.join( (str( ts ),json.dumps( None ),js) ) ) # Load the historical records. This will be robust against all errors except if the first # line of the first history file opened is corrupt, and we therefore cannot get the initial # frame of register data. historical = timestamp( now - random.uniform( -secs_ext, secs + secs_ext )) basisdelay = random.uniform( -basisext, +basisext ) basis = now + basisdelay factor = random.uniform( minfactor, maxfactor ) lookahead = 1.0 on_bad_iframe = random.choice( (loader.RAISE, loader.FAIL, loader.SUPPRESS, loader.SUPPRESS, loader.SUPPRESS) ) on_bad_data = random.choice( (loader.RAISE, loader.FAIL, loader.SUPPRESS, loader.SUPPRESS, loader.SUPPRESS) ) logging.normal( "Playback starts %s (%.1f%%) of history %s-%s, in %.3fs, at x %.2f rate w/%.1fs lookahead, on_bad_iframe=%s, on_bad_data=%s", historical, ( historical.value - oldest.value ) * 100 / ( newest.value - oldest.value ), oldest, newest, basisdelay, factor, lookahead, "SUPPRESS" if on_bad_iframe == loader.SUPPRESS else "FAIL" if on_bad_iframe == loader.FAIL else "RAISE", "SUPPRESS" if on_bad_data == loader.SUPPRESS else "FAIL" if on_bad_data == loader.FAIL else "RAISE" ) ld = loader( path, historical=historical, basis=basis, factor=factor, lookahead=lookahead ) dur = basisext + ( secs_ext + secs + secs_ext ) / factor + basisext + 2*maxlatency # Don't be tooo strict beg = timer() count = 0 while ld: assert timer() - beg < dur, "The loader should have ended" cur,events = ld.load( on_bad_iframe=on_bad_iframe, on_bad_data=on_bad_data ) count += len( events ) logging.normal( "%s loaded up to %s; %d future, %d values: %d events: %s", ld, cur, len( ld.future ), len( ld.values ), len( events ), repr( events ) if logging.root.isEnabledFor( logging.DEBUG ) else reprlib.repr( events )) time.sleep( random.uniform( 0.0, maxlatency )) if on_bad_data == ld.FAIL or on_bad_iframe == ld.FAIL: assert ld.state in (ld.COMPLETE, ld.FAILED) else: assert ld.state == ld.COMPLETE except IframeError as exc: logging.warning( "Detected error on initial frame of registers in first history file; failure expected: %s", exc ) assert ld.state == ld.FAILED and count == 0, "Shouldn't have loaded any events -- only iframe failures expected" except DataError as exc: logging.warning( "Detected error on registers data in a history file; failure expected: %s", exc ) assert ld.state == ld.FAILED except Exception as exc: logging.normal( "Test failed: %s", exc ) for f in files: if os.path.exists( f ): logging.normal( "%s:\n %s", f, " ".join( l for l in open( f ))) else: logging.warning( "%s: Couldn't find file", f ) raise finally: for f in files: logging.detail( "unlinking %s", f ) try: os.unlink( f ) except: pass