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