analysis.py 13 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354
  1. # copyright (c) 2019 PaddlePaddle Authors. All Rights Reserve.
  2. #
  3. # Licensed under the Apache License, Version 2.0 (the "License");
  4. # you may not use this file except in compliance with the License.
  5. # You may obtain a copy of the License at
  6. #
  7. # http://www.apache.org/licenses/LICENSE-2.0
  8. #
  9. # Unless required by applicable law or agreed to in writing, software
  10. # distributed under the License is distributed on an "AS IS" BASIS,
  11. # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  12. # See the License for the specific language governing permissions and
  13. # limitations under the License.
  14. from __future__ import print_function
  15. import argparse
  16. import json
  17. import os
  18. import re
  19. import traceback
  20. def parse_args():
  21. parser = argparse.ArgumentParser(description=__doc__)
  22. parser.add_argument(
  23. "--filename", type=str, help="The name of log which need to analysis."
  24. )
  25. parser.add_argument(
  26. "--log_with_profiler", type=str, help="The path of train log with profiler"
  27. )
  28. parser.add_argument(
  29. "--profiler_path", type=str, help="The path of profiler timeline log."
  30. )
  31. parser.add_argument("--keyword", type=str, help="Keyword to specify analysis data")
  32. parser.add_argument(
  33. "--separator",
  34. type=str,
  35. default=None,
  36. help="Separator of different field in log",
  37. )
  38. parser.add_argument(
  39. "--position", type=int, default=None, help="The position of data field"
  40. )
  41. parser.add_argument(
  42. "--range", type=str, default="", help="The range of data field to intercept"
  43. )
  44. parser.add_argument("--base_batch_size", type=int, help="base_batch size on gpu")
  45. parser.add_argument(
  46. "--skip_steps", type=int, default=0, help="The number of steps to be skipped"
  47. )
  48. parser.add_argument(
  49. "--model_mode", type=int, default=-1, help="Analysis mode, default value is -1"
  50. )
  51. parser.add_argument("--ips_unit", type=str, default=None, help="IPS unit")
  52. parser.add_argument(
  53. "--model_name",
  54. type=str,
  55. default=0,
  56. help="training model_name, transformer_base",
  57. )
  58. parser.add_argument(
  59. "--mission_name", type=str, default=0, help="training mission name"
  60. )
  61. parser.add_argument(
  62. "--direction_id", type=int, default=0, help="training direction_id"
  63. )
  64. parser.add_argument(
  65. "--run_mode", type=str, default="sp", help="multi process or single process"
  66. )
  67. parser.add_argument(
  68. "--index",
  69. type=int,
  70. default=1,
  71. help="{1: speed, 2:mem, 3:profiler, 6:max_batch_size}",
  72. )
  73. parser.add_argument("--gpu_num", type=int, default=1, help="nums of training gpus")
  74. args = parser.parse_args()
  75. args.separator = None if args.separator == "None" else args.separator
  76. return args
  77. def _is_number(num):
  78. pattern = re.compile(r"^[-+]?[-0-9]\d*\.\d*|[-+]?\.?[0-9]\d*$")
  79. result = pattern.match(num)
  80. if result:
  81. return True
  82. else:
  83. return False
  84. class TimeAnalyzer(object):
  85. def __init__(
  86. self, filename, keyword=None, separator=None, position=None, range="-1"
  87. ):
  88. if filename is None:
  89. raise Exception("Please specify the filename!")
  90. if keyword is None:
  91. raise Exception("Please specify the keyword!")
  92. self.filename = filename
  93. self.keyword = keyword
  94. self.separator = separator
  95. self.position = position
  96. self.range = range
  97. self.records = None
  98. self._distil()
  99. def _distil(self):
  100. self.records = []
  101. with open(self.filename, "r") as f_object:
  102. lines = f_object.readlines()
  103. for line in lines:
  104. if self.keyword not in line:
  105. continue
  106. try:
  107. result = None
  108. # Distil the string from a line.
  109. line = line.strip()
  110. line_words = (
  111. line.split(self.separator) if self.separator else line.split()
  112. )
  113. if args.position:
  114. result = line_words[self.position]
  115. else:
  116. # Distil the string following the keyword.
  117. for i in range(len(line_words) - 1):
  118. if line_words[i] == self.keyword:
  119. result = line_words[i + 1]
  120. break
  121. # Distil the result from the picked string.
  122. if not self.range:
  123. result = result[0:]
  124. elif _is_number(self.range):
  125. result = result[0 : int(self.range)]
  126. else:
  127. result = result[
  128. int(self.range.split(":")[0]) : int(
  129. self.range.split(":")[1]
  130. )
  131. ]
  132. self.records.append(float(result))
  133. except Exception as exc:
  134. print(
  135. "line is: {}; separator={}; position={}".format(
  136. line, self.separator, self.position
  137. )
  138. )
  139. print(
  140. "Extract {} records: separator={}; position={}".format(
  141. len(self.records), self.separator, self.position
  142. )
  143. )
  144. def _get_fps(self, mode, batch_size, gpu_num, avg_of_records, run_mode, unit=None):
  145. if mode == -1 and run_mode == "sp":
  146. assert unit, "Please set the unit when mode is -1."
  147. fps = gpu_num * avg_of_records
  148. elif mode == -1 and run_mode == "mp":
  149. assert unit, "Please set the unit when mode is -1."
  150. fps = gpu_num * avg_of_records # temporarily, not used now
  151. print("------------this is mp")
  152. elif mode == 0:
  153. # s/step -> samples/s
  154. fps = (batch_size * gpu_num) / avg_of_records
  155. unit = "samples/s"
  156. elif mode == 1:
  157. # steps/s -> steps/s
  158. fps = avg_of_records
  159. unit = "steps/s"
  160. elif mode == 2:
  161. # s/step -> steps/s
  162. fps = 1 / avg_of_records
  163. unit = "steps/s"
  164. elif mode == 3:
  165. # steps/s -> samples/s
  166. fps = batch_size * gpu_num * avg_of_records
  167. unit = "samples/s"
  168. elif mode == 4:
  169. # s/epoch -> s/epoch
  170. fps = avg_of_records
  171. unit = "s/epoch"
  172. else:
  173. ValueError("Unsupported analysis mode.")
  174. return fps, unit
  175. def analysis(
  176. self, batch_size, gpu_num=1, skip_steps=0, mode=-1, run_mode="sp", unit=None
  177. ):
  178. if batch_size <= 0:
  179. print("base_batch_size should larger than 0.")
  180. return 0, ""
  181. if (
  182. len(self.records) <= skip_steps
  183. ): # to address the condition which item of log equals to skip_steps
  184. print("no records")
  185. return 0, ""
  186. sum_of_records = 0
  187. sum_of_records_skipped = 0
  188. skip_min = self.records[skip_steps]
  189. skip_max = self.records[skip_steps]
  190. count = len(self.records)
  191. for i in range(count):
  192. sum_of_records += self.records[i]
  193. if i >= skip_steps:
  194. sum_of_records_skipped += self.records[i]
  195. if self.records[i] < skip_min:
  196. skip_min = self.records[i]
  197. if self.records[i] > skip_max:
  198. skip_max = self.records[i]
  199. avg_of_records = sum_of_records / float(count)
  200. avg_of_records_skipped = sum_of_records_skipped / float(count - skip_steps)
  201. fps, fps_unit = self._get_fps(
  202. mode, batch_size, gpu_num, avg_of_records, run_mode, unit
  203. )
  204. fps_skipped, _ = self._get_fps(
  205. mode, batch_size, gpu_num, avg_of_records_skipped, run_mode, unit
  206. )
  207. if mode == -1:
  208. print("average ips of %d steps, skip 0 step:" % count)
  209. print("\tAvg: %.3f %s" % (avg_of_records, fps_unit))
  210. print("\tFPS: %.3f %s" % (fps, fps_unit))
  211. if skip_steps > 0:
  212. print("average ips of %d steps, skip %d steps:" % (count, skip_steps))
  213. print("\tAvg: %.3f %s" % (avg_of_records_skipped, fps_unit))
  214. print("\tMin: %.3f %s" % (skip_min, fps_unit))
  215. print("\tMax: %.3f %s" % (skip_max, fps_unit))
  216. print("\tFPS: %.3f %s" % (fps_skipped, fps_unit))
  217. elif mode == 1 or mode == 3:
  218. print("average latency of %d steps, skip 0 step:" % count)
  219. print("\tAvg: %.3f steps/s" % avg_of_records)
  220. print("\tFPS: %.3f %s" % (fps, fps_unit))
  221. if skip_steps > 0:
  222. print(
  223. "average latency of %d steps, skip %d steps:" % (count, skip_steps)
  224. )
  225. print("\tAvg: %.3f steps/s" % avg_of_records_skipped)
  226. print("\tMin: %.3f steps/s" % skip_min)
  227. print("\tMax: %.3f steps/s" % skip_max)
  228. print("\tFPS: %.3f %s" % (fps_skipped, fps_unit))
  229. elif mode == 0 or mode == 2:
  230. print("average latency of %d steps, skip 0 step:" % count)
  231. print("\tAvg: %.3f s/step" % avg_of_records)
  232. print("\tFPS: %.3f %s" % (fps, fps_unit))
  233. if skip_steps > 0:
  234. print(
  235. "average latency of %d steps, skip %d steps:" % (count, skip_steps)
  236. )
  237. print("\tAvg: %.3f s/step" % avg_of_records_skipped)
  238. print("\tMin: %.3f s/step" % skip_min)
  239. print("\tMax: %.3f s/step" % skip_max)
  240. print("\tFPS: %.3f %s" % (fps_skipped, fps_unit))
  241. return round(fps_skipped, 3), fps_unit
  242. if __name__ == "__main__":
  243. args = parse_args()
  244. run_info = dict()
  245. run_info["log_file"] = args.filename
  246. run_info["model_name"] = args.model_name
  247. run_info["mission_name"] = args.mission_name
  248. run_info["direction_id"] = args.direction_id
  249. run_info["run_mode"] = args.run_mode
  250. run_info["index"] = args.index
  251. run_info["gpu_num"] = args.gpu_num
  252. run_info["FINAL_RESULT"] = 0
  253. run_info["JOB_FAIL_FLAG"] = 0
  254. try:
  255. if args.index == 1:
  256. if args.gpu_num == 1:
  257. run_info["log_with_profiler"] = args.log_with_profiler
  258. run_info["profiler_path"] = args.profiler_path
  259. analyzer = TimeAnalyzer(
  260. args.filename, args.keyword, args.separator, args.position, args.range
  261. )
  262. run_info["FINAL_RESULT"], run_info["UNIT"] = analyzer.analysis(
  263. batch_size=args.base_batch_size,
  264. gpu_num=args.gpu_num,
  265. skip_steps=args.skip_steps,
  266. mode=args.model_mode,
  267. run_mode=args.run_mode,
  268. unit=args.ips_unit,
  269. )
  270. try:
  271. if (
  272. int(os.getenv("job_fail_flag")) == 1
  273. or int(run_info["FINAL_RESULT"]) == 0
  274. ):
  275. run_info["JOB_FAIL_FLAG"] = 1
  276. except:
  277. pass
  278. elif args.index == 3:
  279. run_info["FINAL_RESULT"] = {}
  280. records_fo_total = TimeAnalyzer(
  281. args.filename, "Framework overhead", None, 3, ""
  282. ).records
  283. records_fo_ratio = TimeAnalyzer(
  284. args.filename, "Framework overhead", None, 5
  285. ).records
  286. records_ct_total = TimeAnalyzer(
  287. args.filename, "Computation time", None, 3, ""
  288. ).records
  289. records_gm_total = TimeAnalyzer(
  290. args.filename, "GpuMemcpy Calls", None, 4, ""
  291. ).records
  292. records_gm_ratio = TimeAnalyzer(
  293. args.filename, "GpuMemcpy Calls", None, 6
  294. ).records
  295. records_gmas_total = TimeAnalyzer(
  296. args.filename, "GpuMemcpyAsync Calls", None, 4, ""
  297. ).records
  298. records_gms_total = TimeAnalyzer(
  299. args.filename, "GpuMemcpySync Calls", None, 4, ""
  300. ).records
  301. run_info["FINAL_RESULT"]["Framework_Total"] = (
  302. records_fo_total[0] if records_fo_total else 0
  303. )
  304. run_info["FINAL_RESULT"]["Framework_Ratio"] = (
  305. records_fo_ratio[0] if records_fo_ratio else 0
  306. )
  307. run_info["FINAL_RESULT"]["ComputationTime_Total"] = (
  308. records_ct_total[0] if records_ct_total else 0
  309. )
  310. run_info["FINAL_RESULT"]["GpuMemcpy_Total"] = (
  311. records_gm_total[0] if records_gm_total else 0
  312. )
  313. run_info["FINAL_RESULT"]["GpuMemcpy_Ratio"] = (
  314. records_gm_ratio[0] if records_gm_ratio else 0
  315. )
  316. run_info["FINAL_RESULT"]["GpuMemcpyAsync_Total"] = (
  317. records_gmas_total[0] if records_gmas_total else 0
  318. )
  319. run_info["FINAL_RESULT"]["GpuMemcpySync_Total"] = (
  320. records_gms_total[0] if records_gms_total else 0
  321. )
  322. else:
  323. print("Not support!")
  324. except Exception:
  325. traceback.print_exc()
  326. print(
  327. "{}".format(json.dumps(run_info))
  328. ) # it's required, for the log file path insert to the database