diff --git a/app/Http/Controllers/ImportController.php b/app/Http/Controllers/ImportController.php index 4ce137bdd..2d88a7cb3 100644 --- a/app/Http/Controllers/ImportController.php +++ b/app/Http/Controllers/ImportController.php @@ -11,6 +11,7 @@ use App\Jobs\ImportCSV; use Illuminate\Support\Facades\Bus; use App\Services\StatsdAPIClient; +use Illuminate\Support\Facades\Log; class ImportController extends Controller { @@ -19,7 +20,7 @@ class ImportController extends Controller /** @var string */ public const RESOURCE_NAME = 'imports'; - /** + /** * Instantiate a new controller instance. * * @return void @@ -33,11 +34,14 @@ public function __construct(StatsdAPIClient $statsd) /** * Store a newly created resource in storage. * - * @param \Illuminate\Http\Request $request - * @param \App\Services\StatsdAPIClient $statsd + * @param \Illuminate\Http\Request $request + * @param \App\Services\StatsdAPIClient $statsd */ public function store(Request $request, StatsdAPIClient $statsd): JsonResource { + Log::info("============== START IMPORT CONTROLLER =============="); + $start = hrtime(true); + // TODO: Consider using a FormRequest class for auth and validation Gate::authorize('upload-import'); @@ -70,6 +74,8 @@ public function store(Request $request, StatsdAPIClient $statsd): JsonResource ] ]); + Log::info("Start file process"); + $filename = strtr(config('imports.upload.filename_template'), [ ':datetime' => now()->format('Ymd_His'), ':userid' => $request->user()->mw_userid @@ -77,6 +83,13 @@ public function store(Request $request, StatsdAPIClient $statsd): JsonResource $request->file('mismatch_file')->storeAs('mismatch-files', $filename); + $timespan = (hrtime(true) - $start) / 1000000; + + Log::info("Finish file process in {$timespan}ms"); + + + Log::info("Start ImportMeta DB insert"); + $startImportMeta = hrtime(true); $expires = $request->expires ?? now()->add(6, 'months')->toDateString(); $meta = ImportMeta::make([ @@ -89,20 +102,32 @@ public function store(Request $request, StatsdAPIClient $statsd): JsonResource $meta->save(); + $timespan = (hrtime(true) - $startImportMeta) / 1000000; + + Log::info("Finish ImportMeta DB insert in {$timespan}ms"); + + Log::info("Start Bus::chain..."); + + $startChain = hrtime(true); + Bus::chain([ new ValidateCSV($meta), new ImportCSV($meta) ])->dispatch(); - $this->trackImportStats(); + $timespan = (hrtime(true) - $startChain) / 1000000; + Log::info("Finish Bus::chain {$timespan}ms"); + + $this->trackImportStats(); + Log::info("============== END IMPORT CONTROLLER =============="); return new ImportMetaResource($meta); } /** * Display the specified resource. * - * @param \App\Models\ImportMeta $import + * @param \App\Models\ImportMeta $import */ public function show(ImportMeta $import): JsonResource { @@ -116,4 +141,32 @@ public function index() { return ImportMetaResource::collection(ImportMeta::orderByDesc('id')->take(10)->get()); } + +// public function measure($benchmarkables, int $iterations = 1) +// { +// return collect(Arr::wrap($benchmarkables))->map(function ($callback) use ($iterations) { +// return collect(range(1, $iterations))->map(function () use ($callback) { +// gc_collect_cycles(); +// +// $start = hrtime(true); +// +// $callback(); +// +// return (hrtime(true) - $start) / 1000000; +// })->average(); +// })->when( +// $benchmarkables instanceof Closure, +// fn($c) => $c->first(), +// fn($c) => $c->all(), +// ); +// } +// +// public function dd($benchmarkables, int $iterations = 1): void +// { +// $result = collect($this->measure(Arr::wrap($benchmarkables), $iterations)) +// ->map(fn($average) => number_format($average, 3) . 'ms') +// ->when($benchmarkables instanceof Closure, fn($c) => $c->first(), fn($c) => $c->all()); +// +// dd($result); +// } } diff --git a/app/Jobs/ImportCSV.php b/app/Jobs/ImportCSV.php index ef926ce13..d21183dba 100644 --- a/app/Jobs/ImportCSV.php +++ b/app/Jobs/ImportCSV.php @@ -9,6 +9,7 @@ use Illuminate\Queue\SerializesModels; use App\Models\ImportMeta; use App\Models\Mismatch; +use Illuminate\Support\Facades\Log; use Illuminate\Support\Facades\Storage; use App\Services\CSVImportReader; use Illuminate\Support\Facades\DB; @@ -43,6 +44,9 @@ public function __construct(ImportMeta $meta) */ public function handle(CSVImportReader $reader) { + Log::info("======= Start import CSV ======="); + $start = hrtime(true); + $filepath = Storage::disk('local') ->path('mismatch-files/' . $this->meta->filename); @@ -59,6 +63,9 @@ public function handle(CSVImportReader $reader) $this->meta->status = 'completed'; $this->meta->save(); }); + + $timespan = (hrtime(true) - $start) / 1000000; + Log::info("======= End import CSV in {$timespan}ms ======="); } /** diff --git a/app/Jobs/ValidateCSV.php b/app/Jobs/ValidateCSV.php index 57e0c6e8e..47151cdc7 100644 --- a/app/Jobs/ValidateCSV.php +++ b/app/Jobs/ValidateCSV.php @@ -52,20 +52,30 @@ public function handle( WikidataValue $valueValidator, MetaWikidataValue $metaValueValidator ) { + Log::info("Start validating..."); + $start = hrtime(true); + $filepath = Storage::disk('local') ->path('mismatch-files/' . $this->meta->filename); $reader->lines($filepath) ->each(function ($mismatch, $i) use ($statementGuidValidator, $valueValidator, $metaValueValidator) { + Log::info("Start line..."); + $lineStart = hrtime(true); $error = $this->checkFieldErrors($mismatch) ?? $this->checkStatementGuidErrors($mismatch, $statementGuidValidator) ?? $this->checkValueErrors($mismatch, $valueValidator) ?? $this->checkMetaValueErrors($mismatch, $metaValueValidator); + $lineEnd = (hrtime(true) - $lineStart) / 1000000; + Log::info("End line in {$lineEnd}ms..."); if ($error) { throw new ImportValidationException($i, $error); } }); + $timespan = (hrtime(true) - $start) / 1000000; + + Log::info("Finish validating in {$timespan}ms"); } /** @@ -102,6 +112,9 @@ public function failed(Throwable $exception) private function checkFieldErrors($mismatch): ?string { + Log::info("Start checkFieldErrors..."); + $start = hrtime(true); + $rules = config('mismatches.validation'); $validator = Validator::make($mismatch, [ @@ -143,16 +156,20 @@ private function checkFieldErrors($mismatch): ?string ] ]); - if ($validator->stopOnFirstFailure()->fails()) { + $timespan = (hrtime(true) - $start) / 1000000; + Log::info("Finish checkFieldErrors in {$timespan}ms"); return $validator->errors()->first(); } - + $timespan = (hrtime(true) - $start) / 1000000; + Log::info("Finish checkFieldErrors in {$timespan}ms"); return null; } private function checkStatementGuidErrors($mismatch, StatementGuidValue $statementGuidRule): ?string { + Log::info("Start checkStatementGuidErrors..."); + $start = hrtime(true); $validator = Validator::make([ 'item_id' => $mismatch['item_id'], 'statement_guid' => $mismatch['statement_guid'], @@ -161,14 +178,20 @@ private function checkStatementGuidErrors($mismatch, StatementGuidValue $stateme ]); if ($validator->fails()) { + $timespan = (hrtime(true) - $start) / 1000000; + Log::info("Finish checkStatementGuidErrors in {$timespan}ms"); return $validator->errors()->first(); } - + $timespan = (hrtime(true) - $start) / 1000000; + Log::info("Finish checkStatementGuidErrors in {$timespan}ms"); return null; } private function checkValueErrors($mismatch, WikidataValue $valueRule): ?string { + Log::info("Start checkValueErrors..."); + $start = hrtime(true); + // We require a separate validator for wikidata value formatting, // as it must be validated alongside the wikidata property id. $validator = Validator::make([ @@ -181,14 +204,21 @@ private function checkValueErrors($mismatch, WikidataValue $valueRule): ?string ]); if ($validator->fails()) { + $timespan = (hrtime(true) - $start) / 1000000; + Log::info("Finish checkValueErrors in {$timespan}ms"); return $validator->errors()->first(); } + $timespan = (hrtime(true) - $start) / 1000000; + Log::info("Finish checkValueErrors in {$timespan}ms"); return null; } private function checkMetaValueErrors($mismatch, MetaWikidataValue $metaRule): ?string { + Log::info("Start checkMetaValueErrors..."); + $start = hrtime(true); + $validator = Validator::make([ 'meta_wikidata_value' => [ 'property' => $mismatch['property_id'], @@ -199,9 +229,14 @@ private function checkMetaValueErrors($mismatch, MetaWikidataValue $metaRule): ]); if ($validator->fails()) { + $timespan = (hrtime(true) - $start) / 1000000; + Log::info("Finish checkMetaValueErrors in {$timespan}ms"); return $validator->errors()->first(); } + + $timespan = (hrtime(true) - $start) / 1000000; + Log::info("Finish checkMetaValueErrors in {$timespan}ms"); return null; } }