Skip to content

Commit

Permalink
Add benchmark logs
Browse files Browse the repository at this point in the history
  • Loading branch information
@hasanakg
hasanakg committed Feb 12, 2024
1 parent 2c4e64b commit eddc895
Show file tree
Hide file tree
Showing 3 changed files with 103 additions and 8 deletions.
63 changes: 58 additions & 5 deletions app/Http/Controllers/ImportController.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
{
Expand All @@ -19,7 +20,7 @@ class ImportController extends Controller
/** @var string */
public const RESOURCE_NAME = 'imports';

/**
/**
* Instantiate a new controller instance.
*
* @return void
Expand All @@ -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');

Expand Down Expand Up @@ -70,13 +74,22 @@ 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
]);

$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([
Expand All @@ -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
{
Expand All @@ -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);
// }
}
7 changes: 7 additions & 0 deletions app/Jobs/ImportCSV.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);

Expand All @@ -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 =======");
}

/**
Expand Down
41 changes: 38 additions & 3 deletions app/Jobs/ValidateCSV.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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");
}

/**
Expand Down Expand Up @@ -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, [
Expand Down Expand Up @@ -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'],
Expand All @@ -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([
Expand All @@ -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'],
Expand All @@ -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;
}
}

0 comments on commit eddc895

Please sign in to comment.