src/Pure/Tools/build_log.scala
author wenzelm
Sun Oct 09 16:24:54 2016 +0200 (2016-10-09)
changeset 64120 6c5039016321
parent 64119 8094eaa38d4b
child 64150 b10f2ddd7679
permissions -rw-r--r--
record heap sizes;
     1 /*  Title:      Pure/Tools/build_log.scala
     2     Author:     Makarius
     3 
     4 Build log parsing for current and historic formats.
     5 */
     6 
     7 package isabelle
     8 
     9 
    10 import java.io.{File => JFile}
    11 import java.time.ZoneId
    12 import java.time.format.{DateTimeFormatter, DateTimeParseException}
    13 import java.util.Locale
    14 
    15 import scala.collection.mutable
    16 import scala.util.matching.Regex
    17 
    18 
    19 object Build_Log
    20 {
    21   /** directory content **/
    22 
    23   def is_log(file: JFile): Boolean =
    24     List(".log", ".log.gz", ".log.xz").exists(ext => file.getName.endsWith(ext))
    25 
    26   def isatest_files(dir: Path): List[JFile] =
    27     File.find_files(dir.file, file => is_log(file) && file.getName.startsWith("isatest-makeall-"))
    28 
    29   def afp_test_files(dir: Path): List[JFile] =
    30     File.find_files(dir.file, file => is_log(file) && file.getName.startsWith("afp-test-devel-"))
    31 
    32 
    33 
    34   /** settings **/
    35 
    36   object Settings
    37   {
    38     val build_settings = List("ISABELLE_BUILD_OPTIONS")
    39     val ml_settings = List("ML_PLATFORM", "ML_HOME", "ML_SYSTEM", "ML_OPTIONS")
    40     val all_settings = build_settings ::: ml_settings
    41 
    42     type Entry = (String, String)
    43     type T = List[Entry]
    44 
    45     object Entry
    46     {
    47       def unapply(s: String): Option[Entry] =
    48         s.indexOf('=') match {
    49           case -1 => None
    50           case i =>
    51             val a = s.substring(0, i)
    52             val b = Library.perhaps_unquote(s.substring(i + 1))
    53             Some((a, b))
    54         }
    55       def apply(a: String, b: String): String = a + "=" + quote(b)
    56       def getenv(a: String): String = apply(a, Isabelle_System.getenv(a))
    57     }
    58 
    59     def show(): String =
    60       cat_lines(
    61         build_settings.map(Entry.getenv(_)) ::: List("") ::: ml_settings.map(Entry.getenv(_)))
    62   }
    63 
    64 
    65 
    66   /** log file **/
    67 
    68   object Log_File
    69   {
    70     def apply(name: String, lines: List[String]): Log_File =
    71       new Log_File(name, lines)
    72 
    73     def apply(name: String, text: String): Log_File =
    74       Log_File(name, Library.trim_split_lines(text))
    75 
    76     def apply(file: JFile): Log_File =
    77     {
    78       val name = file.getName
    79       val (base_name, text) =
    80         Library.try_unsuffix(".gz", name) match {
    81           case Some(base_name) => (base_name, File.read_gzip(file))
    82           case None =>
    83             Library.try_unsuffix(".xz", name) match {
    84               case Some(base_name) => (base_name, File.read_xz(file))
    85               case None => (name, File.read(file))
    86             }
    87           }
    88       apply(base_name, text)
    89     }
    90 
    91     def apply(path: Path): Log_File = apply(path.file)
    92 
    93 
    94     /* date format */
    95 
    96     val Date_Format =
    97     {
    98       val fmts =
    99         Date.Formatter.variants(
   100           List("EEE MMM d HH:mm:ss O yyyy", "EEE MMM d HH:mm:ss VV yyyy"),
   101           List(Locale.ENGLISH, Locale.GERMAN)) :::
   102         List(
   103           DateTimeFormatter.RFC_1123_DATE_TIME,
   104           Date.Formatter.pattern("EEE MMM d HH:mm:ss yyyy").withZone(ZoneId.of("Europe/Berlin")))
   105 
   106       def tune_timezone(s: String): String =
   107         s match {
   108           case "CET" | "MET" => "GMT+1"
   109           case "CEST" | "MEST" => "GMT+2"
   110           case "EST" => "Europe/Berlin"
   111           case _ => s
   112         }
   113       def tune_weekday(s: String): String =
   114         s match {
   115           case "Die" => "Di"
   116           case "Mit" => "Mi"
   117           case "Don" => "Do"
   118           case "Fre" => "Fr"
   119           case "Sam" => "Sa"
   120           case "Son" => "So"
   121           case _ => s
   122         }
   123 
   124       def tune(s: String): String =
   125         Word.implode(
   126           Word.explode(s) match {
   127             case a :: "M\uFFFDr" :: bs => tune_weekday(a) :: "Mär" :: bs.map(tune_timezone(_))
   128             case a :: bs => tune_weekday(a) :: bs.map(tune_timezone(_))
   129             case Nil => Nil
   130           }
   131         )
   132 
   133       Date.Format.make(fmts, tune)
   134     }
   135 
   136 
   137     /* inlined content */
   138 
   139     def print_props(marker: String, props: Properties.T): String =
   140       marker + YXML.string_of_body(XML.Encode.properties(props))
   141   }
   142 
   143   class Log_File private(val name: String, val lines: List[String])
   144   {
   145     log_file =>
   146 
   147     override def toString: String = name
   148 
   149     def text: String = cat_lines(lines)
   150 
   151     def err(msg: String): Nothing =
   152       error("Error in log file " + quote(name) + ": " + msg)
   153 
   154 
   155     /* date format */
   156 
   157     object Strict_Date
   158     {
   159       def unapply(s: String): Some[Date] =
   160         try { Some(Log_File.Date_Format.parse(s)) }
   161         catch { case exn: DateTimeParseException => log_file.err(exn.getMessage) }
   162     }
   163 
   164 
   165     /* inlined content */
   166 
   167     def find[A](f: String => Option[A]): Option[A] =
   168       lines.iterator.map(f).find(_.isDefined).map(_.get)
   169 
   170     def find_match(regex: Regex): Option[String] =
   171       lines.iterator.map(regex.unapplySeq(_)).find(res => res.isDefined && res.get.length == 1).
   172         map(res => res.get.head)
   173 
   174 
   175     /* settings */
   176 
   177     def get_setting(a: String): Option[Settings.Entry] =
   178       lines.find(_.startsWith(a + "=")) match {
   179         case Some(line) => Settings.Entry.unapply(line)
   180         case None => None
   181       }
   182 
   183     def get_settings(as: List[String]): Settings.T =
   184       for { a <- as; entry <- get_setting(a) } yield entry
   185 
   186 
   187     /* properties (YXML) */
   188 
   189     val xml_cache = new XML.Cache()
   190 
   191     def parse_props(text: String): Properties.T =
   192       xml_cache.props(XML.Decode.properties(YXML.parse_body(text)))
   193 
   194     def filter_props(marker: String): List[Properties.T] =
   195       for (line <- lines; s <- Library.try_unprefix(marker, line)) yield parse_props(s)
   196 
   197     def find_line(marker: String): Option[String] =
   198       find(Library.try_unprefix(marker, _))
   199 
   200     def find_props(marker: String): Option[Properties.T] =
   201       find_line(marker).map(parse_props(_))
   202 
   203 
   204     /* parse various formats */
   205 
   206     def parse_meta_info(): Meta_Info = Build_Log.parse_meta_info(log_file)
   207 
   208     def parse_build_info(): Build_Info = Build_Log.parse_build_info(log_file)
   209 
   210     def parse_session_info(
   211         default_name: String = "",
   212         command_timings: Boolean = false,
   213         ml_statistics: Boolean = false,
   214         task_statistics: Boolean = false): Session_Info =
   215       Build_Log.parse_session_info(
   216         log_file, default_name, command_timings, ml_statistics, task_statistics)
   217   }
   218 
   219 
   220 
   221   /** meta info **/
   222 
   223   object Field
   224   {
   225     val build_engine = "build_engine"
   226     val build_host = "build_host"
   227     val build_start = "build_start"
   228     val build_end = "build_end"
   229     val isabelle_version = "isabelle_version"
   230     val afp_version = "afp_version"
   231   }
   232 
   233   object Meta_Info
   234   {
   235     val empty: Meta_Info = Meta_Info(Nil, Nil)
   236   }
   237 
   238   sealed case class Meta_Info(props: Properties.T, settings: List[(String, String)])
   239   {
   240     def is_empty: Boolean = props.isEmpty && settings.isEmpty
   241   }
   242 
   243   object Isatest
   244   {
   245     val engine = "isatest"
   246     val Start = new Regex("""^------------------- starting test --- (.+) --- (.+)$""")
   247     val End = new Regex("""^------------------- test (?:successful|FAILED) --- (.+) --- .*$""")
   248     val Isabelle_Version = new Regex("""^Isabelle version: (\S+)$""")
   249     val No_AFP_Version = new Regex("""$.""")
   250   }
   251 
   252   object AFP_Test
   253   {
   254     val engine = "afp-test"
   255     val Start = new Regex("""^Start test(?: for .+)? at ([^,]+), (.*)$""")
   256     val Start_Old = new Regex("""^Start test(?: for .+)? at ([^,]+)$""")
   257     val End = new Regex("""^End test on (.+), .+, elapsed time:.*$""")
   258     val Isabelle_Version = new Regex("""^Isabelle version: .* -- hg id (\S+)$""")
   259     val AFP_Version = new Regex("""^AFP version: .* -- hg id (\S+)$""")
   260     val Bad_Init = new Regex("""^cp:.*: Disc quota exceeded$""")
   261   }
   262 
   263   object Jenkins
   264   {
   265     val engine = "jenkins"
   266     val Start = new Regex("""^Started .*$""")
   267     val Start_Date = new Regex("""^Build started at (.+)$""")
   268     val No_End = new Regex("""$.""")
   269     val Isabelle_Version = new Regex("""^Isabelle id (\S+)$""")
   270     val AFP_Version = new Regex("""^AFP id (\S+)$""")
   271     val CONFIGURATION = "=== CONFIGURATION ==="
   272     val BUILD = "=== BUILD ==="
   273     val FINISHED = "Finished: "
   274   }
   275 
   276   private def parse_meta_info(log_file: Log_File): Meta_Info =
   277   {
   278     def parse(engine: String, host: String, start: Date,
   279       End: Regex, Isabelle_Version: Regex, AFP_Version: Regex): Meta_Info =
   280     {
   281       val build_engine = if (engine == "") Nil else List(Field.build_engine -> engine)
   282       val build_host = if (host == "") Nil else List(Field.build_host -> host)
   283 
   284       val start_date = List(Field.build_start -> start.toString)
   285       val end_date =
   286         log_file.lines.last match {
   287           case End(log_file.Strict_Date(end_date)) =>
   288             List(Field.build_end -> end_date.toString)
   289           case _ => Nil
   290         }
   291 
   292       val isabelle_version =
   293         log_file.find_match(Isabelle_Version).map(Field.isabelle_version -> _)
   294       val afp_version =
   295         log_file.find_match(AFP_Version).map(Field.afp_version -> _)
   296 
   297       Meta_Info(build_engine ::: build_host :::
   298           start_date ::: end_date ::: isabelle_version.toList ::: afp_version.toList,
   299         log_file.get_settings(Settings.all_settings))
   300     }
   301 
   302     log_file.lines match {
   303       case line :: _ if line.startsWith(Build_History.META_INFO_MARKER) =>
   304         Meta_Info(log_file.find_props(Build_History.META_INFO_MARKER).get,
   305           log_file.get_settings(Settings.all_settings))
   306 
   307       case Isatest.Start(log_file.Strict_Date(start), host) :: _ =>
   308         parse(Isatest.engine, host, start, Isatest.End,
   309           Isatest.Isabelle_Version, Isatest.No_AFP_Version)
   310 
   311       case AFP_Test.Start(log_file.Strict_Date(start), host) :: _ =>
   312         parse(AFP_Test.engine, host, start, AFP_Test.End,
   313           AFP_Test.Isabelle_Version, AFP_Test.AFP_Version)
   314 
   315       case AFP_Test.Start_Old(log_file.Strict_Date(start)) :: _ =>
   316         parse(AFP_Test.engine, "", start, AFP_Test.End,
   317           AFP_Test.Isabelle_Version, AFP_Test.AFP_Version)
   318 
   319       case Jenkins.Start() :: _
   320       if log_file.lines.contains(Jenkins.CONFIGURATION) ||
   321          log_file.lines.last.startsWith(Jenkins.FINISHED) =>
   322         log_file.lines.dropWhile(_ != Jenkins.BUILD) match {
   323           case Jenkins.BUILD :: _ :: Jenkins.Start_Date(log_file.Strict_Date(start)) :: _ =>
   324             parse(Jenkins.engine, "", start.to(ZoneId.of("Europe/Berlin")), Jenkins.No_End,
   325               Jenkins.Isabelle_Version, Jenkins.AFP_Version)
   326           case _ => Meta_Info.empty
   327         }
   328 
   329       case line :: _ if line.startsWith("\0") => Meta_Info.empty
   330       case List(Isatest.End(_)) => Meta_Info.empty
   331       case _ :: AFP_Test.Bad_Init() :: _ => Meta_Info.empty
   332       case Nil => Meta_Info.empty
   333 
   334       case _ => log_file.err("cannot detect log file format")
   335     }
   336   }
   337 
   338 
   339 
   340   /** build info: produced by isabelle build or build_history **/
   341 
   342   val ML_STATISTICS_MARKER = "\fML_statistics = "
   343   val SESSION_NAME = "session_name"
   344 
   345   object Session_Status extends Enumeration
   346   {
   347     val EXISTING = Value("existing")
   348     val FINISHED = Value("finished")
   349     val FAILED = Value("failed")
   350     val CANCELLED = Value("cancelled")
   351   }
   352 
   353   sealed case class Session_Entry(
   354     chapter: String,
   355     groups: List[String],
   356     threads: Option[Int],
   357     timing: Timing,
   358     ml_timing: Timing,
   359     ml_statistics: List[Properties.T],
   360     heap_size: Option[Long],
   361     status: Session_Status.Value)
   362   {
   363     def finished: Boolean = status == Session_Status.FINISHED
   364   }
   365 
   366   sealed case class Build_Info(sessions: Map[String, Session_Entry])
   367   {
   368     def session(name: String): Session_Entry = sessions(name)
   369     def get_session(name: String): Option[Session_Entry] = sessions.get(name)
   370 
   371     def get_default[A](name: String, f: Session_Entry => A, x: A): A =
   372       get_session(name) match {
   373         case Some(entry) => f(entry)
   374         case None => x
   375       }
   376 
   377     def finished_sessions: List[String] = sessions.keySet.iterator.filter(finished(_)).toList
   378     def finished(name: String): Boolean = get_default(name, _.finished, false)
   379     def timing(name: String): Timing = get_default(name, _.timing, Timing.zero)
   380     def ml_timing(name: String): Timing = get_default(name, _.ml_timing, Timing.zero)
   381   }
   382 
   383   private def parse_build_info(log_file: Log_File): Build_Info =
   384   {
   385     object Chapter_Name
   386     {
   387       def unapply(s: String): Some[(String, String)] =
   388         space_explode('/', s) match {
   389           case List(chapter, name) => Some((chapter, name))
   390           case _ => Some(("", s))
   391         }
   392     }
   393 
   394     val Session_No_Groups = new Regex("""^Session (\S+)$""")
   395     val Session_Groups = new Regex("""^Session (\S+) \((.*)\)$""")
   396     val Session_Finished1 =
   397       new Regex("""^Finished (\S+) \((\d+):(\d+):(\d+) elapsed time, (\d+):(\d+):(\d+) cpu time.*$""")
   398     val Session_Finished2 =
   399       new Regex("""^Finished (\S+) \((\d+):(\d+):(\d+) elapsed time.*$""")
   400     val Session_Timing =
   401       new Regex("""^Timing (\S+) \((\d) threads, (\d+\.\d+)s elapsed time, (\d+\.\d+)s cpu time, (\d+\.\d+)s GC time.*$""")
   402     val Session_Started = new Regex("""^(?:Running|Building) (\S+) \.\.\.$""")
   403     val Session_Failed = new Regex("""^(\S+) FAILED""")
   404     val Session_Cancelled = new Regex("""^(\S+) CANCELLED""")
   405     val Heap = new Regex("""^Heap (\S+) \((\d+) bytes\)$""")
   406 
   407     var chapter = Map.empty[String, String]
   408     var groups = Map.empty[String, List[String]]
   409     var threads = Map.empty[String, Int]
   410     var timing = Map.empty[String, Timing]
   411     var ml_timing = Map.empty[String, Timing]
   412     var started = Set.empty[String]
   413     var failed = Set.empty[String]
   414     var cancelled = Set.empty[String]
   415     var ml_statistics = Map.empty[String, List[Properties.T]]
   416     var heap_sizes = Map.empty[String, Long]
   417 
   418     def all_sessions: Set[String] =
   419       chapter.keySet ++ groups.keySet ++ threads.keySet ++ timing.keySet ++ ml_timing.keySet ++
   420       failed ++ cancelled ++ started ++ ml_statistics.keySet ++ heap_sizes.keySet
   421 
   422 
   423     for (line <- log_file.lines) {
   424       line match {
   425         case Session_No_Groups(Chapter_Name(chapt, name)) =>
   426           chapter += (name -> chapt)
   427           groups += (name -> Nil)
   428 
   429         case Session_Groups(Chapter_Name(chapt, name), grps) =>
   430           chapter += (name -> chapt)
   431           groups += (name -> Word.explode(grps))
   432 
   433         case Session_Started(name) =>
   434           started += name
   435 
   436         case Session_Finished1(name,
   437             Value.Int(e1), Value.Int(e2), Value.Int(e3),
   438             Value.Int(c1), Value.Int(c2), Value.Int(c3)) =>
   439           val elapsed = Time.hms(e1, e2, e3)
   440           val cpu = Time.hms(c1, c2, c3)
   441           timing += (name -> Timing(elapsed, cpu, Time.zero))
   442 
   443         case Session_Finished2(name,
   444             Value.Int(e1), Value.Int(e2), Value.Int(e3)) =>
   445           val elapsed = Time.hms(e1, e2, e3)
   446           timing += (name -> Timing(elapsed, Time.zero, Time.zero))
   447 
   448         case Session_Timing(name,
   449             Value.Int(t), Value.Double(e), Value.Double(c), Value.Double(g)) =>
   450           val elapsed = Time.seconds(e)
   451           val cpu = Time.seconds(c)
   452           val gc = Time.seconds(g)
   453           ml_timing += (name -> Timing(elapsed, cpu, gc))
   454           threads += (name -> t)
   455 
   456         case Heap(name, Value.Long(size)) =>
   457           heap_sizes += (name -> size)
   458 
   459         case _ if line.startsWith(ML_STATISTICS_MARKER) =>
   460           val (name, props) =
   461             Library.try_unprefix(ML_STATISTICS_MARKER, line).map(log_file.parse_props(_)) match {
   462               case Some((SESSION_NAME, session_name) :: props) => (session_name, props)
   463               case _ => log_file.err("malformed ML_statistics " + quote(line))
   464             }
   465           ml_statistics += (name -> (props :: ml_statistics.getOrElse(name, Nil)))
   466 
   467         case _ =>
   468       }
   469     }
   470 
   471     val sessions =
   472       Map(
   473         (for (name <- all_sessions.toList) yield {
   474           val status =
   475             if (failed(name)) Session_Status.FAILED
   476             else if (cancelled(name)) Session_Status.CANCELLED
   477             else if (timing.isDefinedAt(name) || ml_timing.isDefinedAt(name))
   478               Session_Status.FINISHED
   479             else if (started(name)) Session_Status.FAILED
   480             else Session_Status.EXISTING
   481           val entry =
   482             Session_Entry(
   483               chapter.getOrElse(name, ""),
   484               groups.getOrElse(name, Nil),
   485               threads.get(name),
   486               timing.getOrElse(name, Timing.zero),
   487               ml_timing.getOrElse(name, Timing.zero),
   488               ml_statistics.getOrElse(name, Nil).reverse,
   489               heap_sizes.get(name),
   490               status)
   491           (name -> entry)
   492         }):_*)
   493     Build_Info(sessions)
   494   }
   495 
   496 
   497 
   498   /** session info: produced by "isabelle build" **/
   499 
   500   sealed case class Session_Info(
   501     session_name: String,
   502     session_timing: Properties.T,
   503     command_timings: List[Properties.T],
   504     ml_statistics: List[Properties.T],
   505     task_statistics: List[Properties.T])
   506 
   507   private def parse_session_info(
   508     log_file: Log_File,
   509     default_name: String,
   510     command_timings: Boolean,
   511     ml_statistics: Boolean,
   512     task_statistics: Boolean): Session_Info =
   513   {
   514     val xml_cache = new XML.Cache()
   515 
   516     val session_name =
   517       log_file.find_line("\fSession.name = ") match {
   518         case None => default_name
   519         case Some(name) if default_name == "" || default_name == name => name
   520         case Some(name) => log_file.err("log from different session " + quote(name))
   521       }
   522     val session_timing = log_file.find_props("\fTiming = ") getOrElse Nil
   523     val command_timings_ =
   524       if (command_timings) log_file.filter_props("\fcommand_timing = ") else Nil
   525     val ml_statistics_ =
   526       if (ml_statistics) log_file.filter_props(ML_STATISTICS_MARKER) else Nil
   527     val task_statistics_ =
   528       if (task_statistics) log_file.filter_props("\ftask_statistics = ") else Nil
   529 
   530     Session_Info(session_name, session_timing, command_timings_, ml_statistics_, task_statistics_)
   531   }
   532 }